Skip Menu |

This queue is for tickets about the Mail-Log-Trace CPAN distribution.

Report information
The Basics
Id: 108904
Status: patched
Worked: 10 min
Priority: 0/
Queue: Mail-Log-Trace

People
Owner: DStaal [...] usa.net
Requestors: alvin [...] netvel.net
Cc:
AdminCc:

Bug Information
Severity: (no value)
Broken in: (no value)
Fixed in: (no value)



Subject: Connection start predates logfile
Date: Fri, 13 Nov 2015 14:22:38 -0500
To: bug-Mail-Log-Trace [...] rt.cpan.org
From: Alvin Starr <alvin [...] netvel.net>
With the following config: Mail-Log-Trace-1.0101 perl v5.20.3 Linux 4.2.5-201.fc22.x86_64 If I do a $tracer->find_message_info({to_address => '<nobody@nodomain.com>'}) multiple times I get "Connection start predates logfile". On a reasonably busy mail server your going to always get transactions that overlap the edge of the log file. I sort of expect that I should be able to use the following code to print data from the log file. while( $tracer->find_message_info({to_address => '<nobody@nodomain.com>'})) { my $from_address = $tracer->get_from_address(); my $mid = $tracer->get_message_id(); $tracer->clear_message_info(); print "$from_address,$mid\n"; } -- Alvin Starr || voice: (905)513-7688 Netvel Inc. || Cell: (416)806-0133 alvin@netvel.net ||
On 2015-11-13 14:23:03, alvin@netvel.net wrote: Show quoted text
> With the following config: > > Mail-Log-Trace-1.0101 > perl v5.20.3 > Linux 4.2.5-201.fc22.x86_64 > > > If I do a $tracer->find_message_info({to_address => > '<nobody@nodomain.com>'}) > multiple times I get "Connection start predates logfile". > > On a reasonably busy mail server your going to always get transactions > that overlap the edge of the log file. > > I sort of expect that I should be able to use the following code to > print data from the log file. > > while( $tracer->find_message_info({to_address => '<nobody@nodomain.com>'})) > { > my $from_address = $tracer->get_from_address(); > my $mid = $tracer->get_message_id(); > $tracer->clear_message_info(); > print "$from_address,$mid\n"; > }
That exception is expected - Mail::Log::Trace tries to gather all the info on a message, so if it can't it needs to tell you why. You can catch the exception and get all the info it was able to collect from $tracer. (Ideally, handling the fact that some of it will be undefined along the way.) You should then be able to go to the next loop iteration and get the next message's info. If that loop always gets the same message info, that's a bug, and I'll need to look at it. But after a few exceptions, it should run through to the end of the file. (Possibly giving some more exceptions at the end of the file.) The point of this is so that you can handle transactions that overlap the log file correctly - if this module didn't throw any type of exception you'd just get the transaction twice (once for the 'first' log file, and once for the 'second'), both with several undefined values. This way you know which messages need special handling. It's likely that I need to write more documentation, of what errors this module can throw under different circumstances. (Note that my original use case for this module was to parse ~9GB of logs a day... I'm aware how it operates on a busy server. Though my end analysis was 'to slow for production'.)
Subject: Re: [rt.cpan.org #108904] Connection start predates logfile
Date: Mon, 16 Nov 2015 08:44:14 -0500
To: bug-Mail-Log-Trace [...] rt.cpan.org
From: Alvin Starr <alvin [...] netvel.net>
I tried wrapping the find_message_info in a try/catch pair. That did not seem to work all that well and in looking at the code it appears that when the code backs up to try and find the start of the log entry it will backup to the start of the file and leave the maillog pointer at line 0 and start reading from the beginning again. On 11/15/2015 05:48 PM, Daniel T. Staal via RT wrote: Show quoted text
> <URL: https://rt.cpan.org/Ticket/Display.html?id=108904 > > > On 2015-11-13 14:23:03, alvin@netvel.net wrote:
>> With the following config: >> >> Mail-Log-Trace-1.0101 >> perl v5.20.3 >> Linux 4.2.5-201.fc22.x86_64 >> >> >> If I do a $tracer->find_message_info({to_address => >> '<nobody@nodomain.com>'}) >> multiple times I get "Connection start predates logfile". >> >> On a reasonably busy mail server your going to always get transactions >> that overlap the edge of the log file. >> >> I sort of expect that I should be able to use the following code to >> print data from the log file. >> >> while( $tracer->find_message_info({to_address => '<nobody@nodomain.com>'})) >> { >> my $from_address = $tracer->get_from_address(); >> my $mid = $tracer->get_message_id(); >> $tracer->clear_message_info(); >> print "$from_address,$mid\n"; >> }
> That exception is expected - Mail::Log::Trace tries to gather all the info on a message, so if it can't it needs to tell you why. You can catch the exception and get all the info it was able to collect from $tracer. (Ideally, handling the fact that some of it will be undefined along the way.) You should then be able to go to the next loop iteration and get the next message's info. > > If that loop always gets the same message info, that's a bug, and I'll need to look at it. But after a few exceptions, it should run through to the end of the file. (Possibly giving some more exceptions at the end of the file.) > > The point of this is so that you can handle transactions that overlap the log file correctly - if this module didn't throw any type of exception you'd just get the transaction twice (once for the 'first' log file, and once for the 'second'), both with several undefined values. This way you know which messages need special handling. > > It's likely that I need to write more documentation, of what errors this module can throw under different circumstances. > > (Note that my original use case for this module was to parse ~9GB of logs a day... I'm aware how it operates on a busy server. Though my end analysis was 'to slow for production'.)
-- Alvin Starr || voice: (905)513-7688 Netvel Inc. || Cell: (416)806-0133 alvin@netvel.net ||
On 2015-11-16 08:44:38, alvin@netvel.net wrote: Show quoted text
> I tried wrapping the find_message_info in a try/catch pair. > That did not seem to work all that well and in looking at the code it > appears that when the code backs up to try and find the start of the > log > entry it will backup to the start of the file and leave the maillog > pointer at line 0 and start reading from the beginning again.
I have a patch that should help with the 'backs up to the start' issue - it should rachet forward one log file line every time it fails. If you could test and see if it helps that would be good. Also, if you have a sample of a log file that's causing issues for you that I could use to test against it would be helpful. Just something with two entries for the same address, with the first being incomplete - I don't need a whole log file, but I'm not working in an environment where I have access to raw logs on a daily basis anymore. (Anonymize the data, of course.)
Subject: patch_commit_15ebff8023aa.patch
diff --git lib/Mail/Log/Trace/Postfix.pm lib/Mail/Log/Trace/Postfix.pm index 4679aebbbd778b922c64d9ef1cd5b090874d3323..88efe470c1165466f749c3525da7be0945deaca6 100644 --- lib/Mail/Log/Trace/Postfix.pm +++ lib/Mail/Log/Trace/Postfix.pm @@ -178,8 +178,8 @@ sub find_message_info { my $msg_info = $self->_parse_args($argref, 1); my $maillog = $self->_get_log_parser(); - # So we can save something in it later. - my $begin_log_line; + # Save where we are right now. + my $begin_log_line = $maillog->get_line_number(); # Read backwards until we find the start of the connection my $start_found = 0; @@ -254,6 +254,7 @@ sub find_message_info { # Check to see if we found it, and throw an error if we didn't. if ( !$start_found ) { + $maillog->go_forward(); # Start searching at the *next* line for the next search. Mail::Log::Exceptions::Message::IncompleteLog->throw('Connection start predates logfile.'); }