On Tue, Mar 10, 2015 at 09:21:31AM -0400, James B. Byrne wrote:
> Mar 10 08:44:51 inet08 postfix/smtp[4688]: > mx00.1and1.com[74.208.5.3]:25:
> EHLO inet08.hamilton.harte-lyne.ca
> Mar 10 08:44:51 inet08 postfix/smtp[4688]: < mx00.1and1.com[74.208.5.3]:25:
> 250-perfora.net Hello inet08.hamilton.harte-lyne.ca [216.185.71.28]
A well-formed EHLO was sent and accepted.
> Mar 10 08:44:51 inet08 postfix/smtp[4688]: > EHLO
> inet08.hamilton.harte-lyne.ca
> Mar 10 08:44:51 inet08 postfix/smtp[4688]: < 250-perfora.net Hello
> inet08.hamilton.harte-lyne.ca [216.185.71.28]
Ditto after STARTTLS.
> Mar 10 08:44:51 inet08 postfix/smtp[4688]: > MAIL FROM:<[email protected]>
> SIZE=1130
> Mar 10 08:44:51 inet08 postfix/smtp[4688]: < 250 Requested mail action okay,
> completed
> Mar 10 08:44:51 inet08 postfix/smtp[4688]: > RCPT
> TO:<[email protected]>
> Mar 10 08:44:52 inet08 postfix/smtp[4688]: < 250 OK
> Mar 10 08:44:52 inet08 postfix/smtp[4688]: > DATA
> Mar 10 08:44:52 inet08 postfix/smtp[4688]: < 354 Start mail input; end with
> <CRLF>.<CRLF>
> Mar 10 08:44:52 inet08 postfix/smtp[4688]: > .
> Mar 10 08:44:52 inet08 postfix/smtp[4688]: < 250 Requested mail action okay,
> completed: id=0MThqw-1Y4oQl30AC-00QU3L
And the message got through.
> Mar 10 08:44:52 inet08 postfix/smtp[4688]: 72803609C3:
> to=<[email protected]>,
> relay=mx00.1and1.com[74.208.5.3]:25, delay=2.1,
> delays=0.1/0.09/0.97/0.99, dsn=2.0.0, status=sent
> (250 Requested mail action okay, completed: id=0MThqw-1Y4oQl30AC-00QU3L)
Also per the non-verbose logging.
> The original messages seem to have been accepted initially as well:
>
> Mar 9 11:17:08 inet08 postfix/smtp[31780]: C98B061210:
> to=<[email protected]>,
> relay=mx01.1and1.com[74.208.5.21]:25, delay=2.4,
> delays=0.07/0/1.2/1.1, dsn=2.0.0, status=sent (250 Requested mail
> action okay, completed: id=0MIfHC-1YSmVP0rLU-002Hww)
> Mar 9 11:17:08 inet08 postfix/smtp[31780]: C98B061210:
> to=<[email protected]>,
> relay=mx01.1and1.com[74.208.5.21]:25, delay=2.4,
> delays=0.07/0/1.2/1.1, dsn=2.0.0, status=sent (250 Requested mail
> action okay, completed: id=0MIfHC-1YSmVP0rLU-002Hww)
One message, two recipients. negligible delay, but you might do
better with the attached "collate" script.
# perl collate /var/log/maillog |
perl -ne 'BEGIN {$/="\n\n"; $relay = shift} print if
m{relay=\Q$relay\E\[}o' \
mx01.1and1.com
Which shows related logging.
> But these are the messages that were later reported has giving a 501
> error.
Post largely unmunged logs for this claim. (You can obfuscate
address localparts if you like).
--
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 $i = 0;
my %seqno;
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"};
$seqno{$qid} = ++$i;
next;
}
my $qid = $smtpd{$pid}->{"qid"};
$transaction{$qid} .= $_
if (defined($qid) && exists $transaction{$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} = $_;
$seqno{$qid} = ++$i;
}
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} .= $_;
$seqno{$qid} = ++$i if (! exists $seqno{$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};
$seqno{$newid} = ++$i if (! exists $seqno{$newid});
}
next;
}
if ($isagent{$command}) {
if (m{\G(\w+): to=}gc) {
my $qid = "$inst/$1";
if (defined($transaction{$qid})) {
$transaction{$qid} .= $_;
}
}
next;
}
}
# Dump logs of incomplete transactions.
foreach my $qid (sort {$seqno{$a} <=> $seqno{$b}} keys %transaction) {
print $transaction{$qid}, "\n";
}
