Discussion:
Logging TLS level and used cipher in sent()
(too old to reply)
Toni Mattila
2013-02-02 15:59:26 UTC
Permalink
Hi All,

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.

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.

Thanks,
Toni Mattila
Viktor Dukhovni
2013-02-02 20:14:32 UTC
Permalink
Post by Toni Mattila
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.
Post by Toni Mattila
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;
}
}
Loading...