Late Logging...

ali_kerem has asked for the wisdom of the Perl Monks concerning the following question:

Hello All,

I have a problem about logging in my code ( which is shared below ). My code is reading IBM MQ to get new data each 5 seconds. The code is working but logging is done once in 2 minutes. I mean when I tail the log file, I see it as nothing happens but then, after approximately 2 minutes logs appear as bulk, then stops again. While I'm expecting it to flow, like a normal log file should do, it does bulk printing to log file...

You can check the whole code below, and if there are wrong parts, please make me fix it. Thanks in advance.

#!/usr/bin/perl
# IBM Message Queue Reader
use warnings;
use strict;
use Config::Simple;
use MQSeries;
use MQSeries::Queue;
use MQSeries::QueueManager;
use XML::Simple;
use POSIX;
use Time::Local;
use Data::Dumper;

# Read MQ Settings from config file
my $conf = new Config::Simple("/customS/config.ini");
my $qmgr = $conf->param('MQConf.QueueManager');
my $chnl = $conf->param('MQConf.ChannelName');
my $ipad = $conf->param('MQConf.IPAddress');
my $port = $conf->param('MQConf.Port');
my $qnam = $conf->param('MQConf.Queue');
my $xDir = $conf->param('Folder.XMLunread');

my ($queue,$qmgr_obj);



while(1)
{

        print "".(localtime)." - Trying to open Queue Manager: $qmgr w
+ith Channel: $chnl ...\n";
        # Open Queue Manager with defined settings
        if (
                $qmgr_obj = MQSeries::QueueManager->new(
                QueueManager    => $qmgr,
                ClientConn      => {
                        ChannelName     => $chnl,
                        TransportType   => 'TCP',
                        ConnectionName  => "$ipad($port)",
                        MaxMsgLength    => 16 * 1024 * 1024
                        }
                )
        )
        {       print "".(localtime)." - Queue Manager $qmgr has been 
+opened succesfully.\n";   }
        else
        {       print "".(localtime)." - Can't connect to the queue ma
+nager, quitting...\n";    }
         ;;
         ;;
        print "".(localtime)." - Trying to open Queue: $qnam...\n";
        if (
        # Open Queue with defined settings
                $queue = MQSeries::Queue->new(
                QueueManager    => $qmgr_obj
                , Queue         => $qnam
                , Mode          => 'input'
                )
        )
        {       print "".(localtime)." - Queue $qnam has been opened s
+uccesfully.\n";   }
        else
        {       print "".(localtime)." - Can't connect to the queue, q
+uitting...\n";    }
         ;;
         ;;
        my $c=1;
        while ( $c==1 )
        {
                my $getmessage  = MQSeries::Message->new();
                my $dataFromMQ;
                $queue->Get(
                        Message => $getmessage, # Get Queue's Message 
+portion
                        Sync    => 0,   # 0 removes message from queue
+, 1 keeps message in queue
                );
                # or warn(
                #       "".(localtime).
                #       "Unable to get message\n" .
                #       "CompCode = " . $queue->CompCode() . "\n" .
                #       "Reason = " . $queue->Reason() . "\n");

                if ( defined $getmessage->Data )
                {

                        print "".(localtime)." - got a message from MQ
+...\n";
                         ;; # Get current time as Array
                        my @cTimeA      = POSIX::strftime("%Y-%m-%dT%H
+:%M:%S", gmtime) =~ /(\d+)/g;
                         ;; # Convert Current Time ----Second-----,---
+Minute---,------Hour------,-----Day------,----Month-----,----Year---
                        print "Current time GMT values; ".$cTimeA[3]."
+:".$cTimeA[4].":".$cTimeA[5]." ".$cTimeA[2]."-".$cTimeA[1]."-".$cTime
+A[0]."\n";
                        my $epoch       = timelocal($cTimeA[5],$cTimeA
+[4],$cTimeA[3],$cTimeA[2],$cTimeA[1]-1,$cTimeA[0]);
                         ;; # Put message time info into array(s)
                        my @qDate= $getmessage->{MsgDesc}->{PutDate}=~
+ /(\d{4})(\d\d)(\d\d)/;
                        my @qTime= $getmessage->{MsgDesc}->{PutTime}=~
+ /(\d?)(\d\d)(\d\d)(\d\d)(\d\d)$/;
                         ;; # Get epoch time of message ---Second----,
+---Minute----,----Hour-----,-----Day-----,----Month----,----Year---
                        print "Message PutTime GMT values; ".$qTime[1]
+.":".$qTime[2].":".$qTime[3]." ".$qDate[2]."-".$qDate[1]."-".$qDate[0
+]."\n";
                        my $qTimeE = timelocal($qTime[3],$qTime[2],$qT
+ime[1],$qDate[2],$qDate[1]-1,$qDate[0]);

                        print "".(localtime)." - epoch time is ".$epoc
+h." and mq time is ".$qTimeE."\n";
                         ;; # Epoch Time minus 1 hour is => $epoch - 3
+600
                         ;; # If message time is older than 10 minutes
+ ignore it
                        unless ( $qTimeE <= ($epoch - 600) )
                        {
                                 ;; # Convert Message's Data to XML
                                my $xmlData     = XMLin($getmessage->D
+ata);
                                my @timeA;      # Time Array    = $xml
+Data->{STO}=~ /(\d+)/g;
                                 ;; # Check Time of Flights
                                #if ($xmlData->{AnnouncementCode} eq "
+11")
                                #{ @timeA       = $xmlData->{ATO}=~ /(
+\d+)/g; }
                                #else
                                #{
                                @timeA  = $xmlData->{STO}=~ /(\d+)/g;
                                #}
                                 ;; ############
                                my $timeS       = join "", @timeA; # P
+ut TimeA Values into String
                                #my $timeE      = timelocal($timeA[5],
+$timeA[4],$timeA[3],$timeA[2],$timeA[1],$timeA[0]);
                                my $filename    = $xmlData->{UniqueID}
+.'_'.$xmlData->{AnnouncementCode}.'_'.$timeS.'.xml';

                                print "filename is ".$filename."\n";
                                open(FILE,'>',"$xDir/$filename") or di
+e "Can't write file '$xDir\/$filename' [$!]\n";
                                print FILE $getmessage->Data;
                                close(FILE);
                        }
                        else
                        {
                                print "".(localtime)." - message put t
+ime is older than 10 minutes...\n";
                        }
                }
                else
                {
                        if ( $queue->{Reason} == 2033 )
                        {
                                ;; # Reason 2033 means queue is empty
                                print "".(localtime)." - Message Queue
+ is empty, checking it again in 5 seconds...\n";
                                sleep 5;
                        }
                        elsif ( $queue->{Reason} == 2009 )
                        {
                                print "".(localtime)." - Due to MQ Err
+or 2009, connection will be restarted...\n";
                                sleep 10;
                        }
                        else
                        {
                                print "".(localtime)." - Unable to get
+ message. Reason is ",$queue->{Reason},", Completion Code is ",$queue
+->{CompCode},", re-trying in 5 seconds...\n";
                                sleep 5;
                        }
                        #$c++;
                }
         ;; # End of Inner WHILE Loop
        }
         ;; # Wait 5 seconds before retrying...
        #sleep 5;
 ;; # End of Infinite WHILE Loop
}

my $EoF = "End of File";
[download]

Comment on Late Logging... Download Code

Replies are listed 'Best First'.
Re: Late Logging... by rjt (Curate) on Jul 06, 2013 at 11:39 UTC
My guess would be that you're Suffering from Buffering, but there may be other problems; your code was a bit long for me to review right now. See How do I post a question effectively? for tips on reducing your code to a minimum. See File::Tail for an interface specifically geared towards reading files that are appended to.	[reply]
Re^2: Late Logging... by ali_kerem (Acolyte) on Jul 06, 2013 at 12:44 UTC
But I didnt know where is the error. That is the reason I posted the whole code. Now I fixed it with your help, thank you.	[reply]
Re: Late Logging... by roboticus (Chancellor) on Jul 06, 2013 at 14:10 UTC
ali_kerem: I don't have an answer for you, but here are some notes that may make it simpler to get an answer. First, unless someone has an IBM MQ setup somewhere, they're not going to be able to test your code and find the problem(s). The more difficult it is for someone to reproduce the problem, the fewer responses you'll get. You can increase the number of people who will read your code by structuring it well--that way someone may be able to help even if they can't read the code. I'd suggest that you lay out your code with smaller indents when you post a question so it doesn't wrap. Line wrapping on more than a couple of lines makes the code inscrutable. I'd go with 3-4 spaces per indent level. While you're at it, make your indentation *consistent* because it will help the clarity of your code. Unusual formatting will also make things a little harder to read. I don't know why, but you frequently use a comment structure like: `;; # A comment preceded by two null statements ... why?` [download] Next, break your program into subroutines. Even if your program is relatively simple (as yours is), breaking it into smaller simpler pieces makes it easier to understand and maintain. For example: You use the construct `print "".(localtime)." - Some Logging Message.\n";`. Even something as simple as this can profitably be turned into a subroutine. Even a subroutine that's called only once can clarify and improve the organization of your code. It lets you move irrelevant details out of the way. I've split out your queue opening code and the message processing code into their own subroutines. Since your message mentions that your code is largely working, it makes it much easier to ignore the part that opens the queues, which is obviously working since you can read messages. When you simplify your code, you won't need noisy comments like "end of infinite while loop" because you can see the start of the loop just a couple of lines above. Many of your comments are just noise. If you structure your program better your code can document itself. Near the top, you have a print statement mentioning that you're opening a queue manager, and then you put in a comment that you're opening a queue manager "with defined settings". The print statement by itself is documentation enough, and clause "with defined settings" really doesn't add any information, so it's just visual noise. Further, if you break your code into subroutines, the subroutine names themselves become documentation. If you have any code that's commented out, be sure to remove it unless it's relevant to the question, or it's just another distraction. If you rearrange some statements then you can make the code a bit simpler as well as making some comments do double-duty. For example the bit where you're printing in sec/min/hr/day/month/year format: If you do them next to each other, the comment for the first one works for the second one, too. Put similar code close together when you can. Since this is another of my occasional long posts, the rest is in readmore tags. That way you don't have to suffer through the entire node unless you really want to. Read more... (3 kB) After I apply these suggestions to your code, I came up with the following. I didn't reformat it much, nor did I test it. But it should be a little easier to read: Read more... (6 kB) Now that the code is structured better, how would we go about helping you? First we'd notice that the main control loop is straightforward. You first open the queue and the queue manager, and then we start retrieving and processing messages. By reading your original post we know you're processing messages successfully, so we can ignore the open_queue_manager, open_queue and get_message subroutines on the first pass, as they seem to work. We start by looking over the process_message routine. The process_message routine just checks the time to see whether the message is worth doing anything with or not, and there's no time delay, so we next look over the convert_to_XML_file routine. It's just reading the data and writing an XML file. That doesn't look too bad, so presumably the delay isn't in there, either. If you included some log output, I'd probably start looking at the interval between each message and each outer loop. If there was consistently only one message in the inner loop between each outer loop, I'd suspect that the code wasn't properly processing all messages in the queue before stopping. On the other hand, if there are multiple messages processed between each outer loop, I'd check the amount of time between messages to see if there's probably an issue in the code taking too long. If I couldn't find any problems in the logs, I'd look through the code for sleep calls, and verify that they're occurring in "reasonable" locations. It's easy with so many if statements to have one accidentally in the success path and slow things down. Sorry the post is so long, but I didn't have time to tune it up and make it shorter. ...roboticus When your only tool is a hammer, all problems look like your thumb.	[reply] [d/l] [select]
Re^2: Late Logging... by ali_kerem (Acolyte) on Jul 09, 2013 at 11:28 UTC
Thank you for the long post, I'll try to learn more by your post. Only thing I did not undestand was; ...The way you have it structured now, you'll have two messages for opening the queue manager, two more for opening the queue, and then the logging information for processing your messages. Also, each time you open your queue manager you print the configuration even though it never changes. I open the queue once and it works for days and opening message prints only once, the rest is "queue is empty" message mostly or errors. Anyway, I downloaded your code and started working, I hope I'll learn from it, thank you.	[reply]
Re^3: Late Logging... by roboticus (Chancellor) on Jul 09, 2013 at 11:36 UTC
ali_kerem: Since you had the whole thing wrapped up in a while loop, I was thinking that it would frequently drop out and then restart. Since it's an infrequent message, then just ignore my comment. ...roboticus When your only tool is a hammer, all problems look like your thumb.	[reply]