Re: Late Logging...

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.

Pay attention to your control structures, too. Your unless block is less legible than it could be. Typically when you read code you don't want to have to stack too much information up in your head. So it's helpful to dispense with things quickly where it makes sense. Each time you increase a level of indentation, you've increase the memory burden while you're going through your code. So your:

while (condition) {
    ...
    unless (condition) {
        long
        block
        of
        code
    }
    else {
        print "Error message\n";
    }
}
[download]

Can easily simplify to the following. If we don't care about a message, then make the decision and immediately discard it and move on to the next one:

while (condition) {
    ...
    if (condition) {
        print "Error message\n";
        next;
    }

    long
    block
    of
    code
}
[download]

Similarly, if you have an if statement and you return at the end of the true clause, you don't need an else clause. In other words you can convert this:

if (condition) {
   some code that
   you do sometimes
   return 1;
}
else {
   code you do at other times
}
[download]

to this:

if (condition) {
   some code that
   you do sometimes
   return 1;
}
# Now that we have the special cases out of the way...
code you do at other times
[download]

Pay attention to what you're logging, as well. Each logging statement adds clutter to both your program *and* your log output. 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'd print the configuration once, at the start of the program. Then, if you need to know when each cycle begins, add a log message at the beginning of the cycle. You needn't log successful opens: The absence of error messages conveys that information already.

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:

#!/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);

LOG("##### START #### Queue Manager: $qmgr Channel: $chnl");

while(1)
{
    LOG("Processing queue");
    if (!open_queue_manager() or !open_queue()) {
        sleep 10;
        next;
    }

    while (1)
    {
        my $getmessage = get_message();
        last unless defined $getmessage;

        process_message($getmessage);
    }
}

sub process_message {
    my $message = shift;

    # Get current time (cTimeA) and message time (qDate, qTime)
    my @cTimeA      = POSIX::strftime("%Y-%m-%dT%H:%M:%S", gmtime) =~ 
+/(\d+)/g;
    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)$/;

    print "Current time GMT values; "
    #  --second---   ---minute---   ----hour---
    .  $cTimeA[3].":".$cTimeA[4].":".$cTimeA[5]." "
    #  ----day----   ----month---   ----year---
    .  $cTimeA[2]."-".$cTimeA[1]."-".$cTimeA[0]."\n";

    print "Message PutTime GMT values; "
    .  $qTime[1]. ":".$qTime[2]. ":".$qTime[3]." "
    .  $qDate[2]. "-".$qDate[1]. "-".$qDate[0]."\n";

    # Epoch time is in seconds
    my $epoch       = timelocal($cTimeA[5],$cTimeA[4],$cTimeA[3],$cTim
+eA[2],$cTimeA[1]-1,$cTimeA[0]);
    my $qTimeE = timelocal($qTime[3],$qTime[2],$qTime[1],$qDate[2],$qD
+ate[1]-1,$qDate[0]);
    LOG("epoch time is ".$epoch." and mq time is ".$qTimeE);;

    if ( $qTimeE <= ($epoch - 10*60) ) {
        convert_to_XML_file($getmessage->Data);
    }
    else {
        LOG("message put time is older than 10 minutes..");
    }
}

sub convert_to_XML_file {
    my $xmlData     = XMLin($getmessage->Data);
    my @timeA;      # Time Array    = $xmlData->{STO}=~ /(\d+)/g;

    # Check Time of Flights
    @timeA  = $xmlData->{STO}=~ /(\d+)/g;

    my $timeS       = join "", @timeA; # Put TimeA Values into String
    my $filename    = $xmlData->{UniqueID}.'_'.$xmlData->{Announcement
+Code}.'_'.$timeS.'.xml';

    print "filename is ".$filename."\n";
    open(FILE,'>',"$xDir/$filename") or die "Can't write file '$xDir\/
+$filename' [$!]\n";
    print FILE $getmessage->Data;
    close(FILE);
}

sub get_message {
    my $getmessage  = MQSeries::Message->new();
    $queue->Get(
        Message => $getmessage, # Get Queue's Message portion
        Sync    => 0,   # 0 removes message from queue, 1 keeps messag
+e in queue
    );

    if (! defined $getmessage->Data) {
        if ( $queue->{Reason} == 2033 )
        {
            LOG("Message Queue is empty, checking it again in 5 second
+s.");
            sleep 5;
        }
        elsif ( $queue->{Reason} == 2009 )
        {
            LOG("Due to MQ Error 2009, connection will be restarted.."
+);
            sleep 10;
        }
        else
        {
            LOG("Unable to get message. Reason is $queue->{Reason}, "
               ."Completion Code is $queue->{CompCode}, "
               ."re-trying in 5 seconds..");
            sleep 5;
        }
        return undef;
    }
    return $getmessage;
}

sub open_queue_manager {
    if (
        $qmgr_obj = MQSeries::QueueManager->new(
        QueueManager    => $qmgr,
        ClientConn      => {
            ChannelName     => $chnl,
            TransportType   => 'TCP',
            ConnectionName  => "$ipad($port)",
            MaxMsgLength    => 16 * 1024 * 1024
            }
        )
    )
    { return 1;  }
    LOG("Can't connect to the queue manager, quitting..");
    return 0;
}

sub open_queue {
    if (
        $queue = MQSeries::Queue->new(
        QueueManager    => $qmgr_obj
        , Queue         => $qnam
        , Mode          => 'input'
        )
    )
    { return 1;  }
    LOG("Can't connect to the queue, quitting..");
    return 0;
}

sub LOG {
    print (localtime) . " - " . $msg . ".\n";
}
[download]

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.

Comment on Re: Late Logging... Select or Download Code

Replies are listed 'Best First'.
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]