On Sat, Feb 02, 2013 at 05:59:26PM +0200, Toni Mattila wrote:
> I'm looking for pointers how to get this information:
> postfix/smtp[y]: Trusted TLS connection established to
> mail.server.tld[x.x.x.x]:25: TLSv1 with cipher AES256-SHA (256/256
> bits)
>
> added to the log line that is generated by the sent() as now it's
> pretty hard or time consuming to grep from logs if the recipient was
> encrypted as that tls_client_start() doesn't log the queue ID.
Your log parser writing skills are the problem here. Extracing this
from the logs is not difficult. Every line logged by smtp(8) before
ogging a "qid: to=..." line is related to that final log entry.
Just use a script to collate the log entries into a single entry.
> Background: I'm using smtp_tls_policy_maps to enforce certain next
> hops to use "encrypt" but for rest of the next-hops I'd like to
> produce reports whether TLS was used/was available.
I once wrote a more comprehensive script (called "collate") that
collates all the log entries for a given queue-id into a single
paragraph terminated by blank line. A parser can then read these
one paragraph at a time and extract the various information about
each "transaction" (queue-id). Below my signature is a quick new
variant.
The script could be enhanced to checkpoint state at the end of each
run so that starting with the next log file (say a day later) never
loses message that straddle log file boundaries. Perhaps someone
wants to tackle that and even deal with potential "memory leaks" for
transactions that never complete by flushing sufficiently old state
(sometimes the sender abandons a transaction midstream, but smtpd(8)
and cleanup(8) may generate a queue file that never becomes active).
A more modest enhancement would be to prepend local(8)'s
"forwarded as <new-queue-id>" log entries to the start of
the resulting transaction (similar to the existing bounce(8)
logic).
Contributions welcome. For the OP it suffices to simply collate
smtp(8) log entries with the same pid. This is easy, and does not
require any changes to the delivery completion log format.
--
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;
}
}
