On Thu, Feb 20, 2014 at 06:51:09AM -0500, Wietse Venema wrote:
> To fully understand what happens with a particular message requires
> a stateful logfile processor.
I tend to use the admittedly imperfect, but sufficiently useful
"collate" Perl script I slapped together. A fancier version would
checkpoint data about messages not fully processed at the end of
the current input stream, and allow a future invocation to pick up
where the previous one left off. One might generate such checkpoints
at the end of each day of logs, ...
The simple version below my signature does not accurately report
on messages whose lifetime straddles log file boundaries.
Its output is blank-line delimited, in order of queue exit time.
One can search for messages matching some patter (e.g. a queue-id)
via:
gunzip -c logfile.gz |
perl collate |
perl -ne 'BEGIN {$/="\n\n"} print if m{some-pattern};'
--
Viktor.
#! /usr/bin/perl
use strict;
use warnings;
# Postfix delivery agents
my @agents = qw(discard error lmtp local pipe smtp virtual);
my $instre = qr{(?x)
\A # Absolute line start
(?:\S+ \s+){3} # Timestamp, adjust for other time formats
\S+ \s+ # Hostname
(postfix(?:-\S+)?)/ # postfix instance
};
my $cmdpidre = qr{(?x)
\G # Continue from previous match
(\S+)\[(\d+)\]:\s+ # command[pid]:
};
my %smtpd;
my %smtp;
my %transaction;
my %isagent = map { ($_, 1) } @agents;
while (<>) {
next unless m{$instre}ogc; my $inst = $1;
next unless m{$cmdpidre}ogc; my $command = $1; my $pid = $2;
if ($command eq "smtpd") {
if (m{\Gconnect from }gc) {
# Start new log
$smtpd{$pid}->{"log"} = $_; next;
}
$smtpd{$pid}->{"log"} .= $_;
if (m{\G(\w+): client=}gc) {
# Fresh transaction
my $qid = "$inst/$1";
$smtpd{$pid}->{"qid"} = $qid;
$transaction{$qid} = $smtpd{$pid}->{"log"};
next;
}
my $qid = $smtpd{$pid}->{"qid"};
$transaction{$qid} .= $_ if (defined($qid));
delete $smtpd{$pid} if (m{\Gdisconnect from}gc);
next;
}
if ($command eq "pickup") {
if (m{\G(\w+): uid=}gc) {
my $qid = "$inst/$1";
$transaction{$qid} = $_;
}
next;
}
# bounce(8) logs transaction start after cleanup(8) already logged
# the message-id, so the cleanup log entry may be first
#
if ($command eq "cleanup") {
next unless (m{\G(\w+): }gc);
my $qid = "$inst/$1";
$transaction{$qid} .= $_;
next;
}
if ($command eq "qmgr") {
next unless (m{\G(\w+): }gc);
my $qid = "$inst/$1";
if (defined($transaction{$qid})) {
$transaction{$qid} .= $_;
if (m{\Gremoved$}gc) {
print delete $transaction{$qid}, "\n";
}
}
next;
}
# Save pre-delivery messages for smtp(8) and lmtp(8)
#
if ($command eq "smtp" || $command eq "lmtp") {
$smtp{$pid} .= $_;
if (m{\G(\w+): to=}gc) {
my $qid = "$inst/$1";
if (defined($transaction{$qid})) {
$transaction{$qid} .= $smtp{$pid};
}
delete $smtp{$pid};
}
next;
}
if ($command eq "bounce") {
if (m{\G(\w+): .*? notification: (\w+)$}gc) {
my $qid = "$inst/$1";
my $newid = "$inst/$2";
if (defined($transaction{$qid})) {
$transaction{$qid} .= $_;
}
$transaction{$newid} =
$_ . $transaction{$newid};
}
next;
}
if ($isagent{$command}) {
if (m{\G(\w+): to=}gc) {
my $qid = "$inst/$1";
if (defined($transaction{$qid})) {
$transaction{$qid} .= $_;
}
}
next;
}
}
