Problems with 5.1.1 milter

[Mark Sapiro]

On Fri, 12 Oct 2018 07:40:40 -0400 Shawn Iverson via MailScanner
<mailscanner at lists.mailscanner.info> wrote:

> Ok.  I'll run some tests and see what happens.  Were both recipients in the
> To: field?

I have run a simple test with a message with one local and one remote
recipient.

I get this in the log:

> Oct 12 18:16:23 msapiro postfix/smtpd[26916]: connect from msapiro-enet.attlocal.net[10.211.115.100]
> Oct 12 18:16:23 msapiro postfix/smtpd[26916]: 7002C340121: client=msapiro-enet.attlocal.net[10.211.115.100]
> Oct 12 18:16:23 msapiro postfix/cleanup[26921]: 7002C340121: message-id=<20181013011623.7002C340121 at msapiro.net>
> Oct 12 18:16:23 msapiro postfix/cleanup[26921]: 7002C340121: milter-discard: END-OF-MESSAGE from msapiro-enet.attlocal.net[10.211.115.100]: milter triggers DISCARD action; from=<mark at msapiro.net> to=<mark at ms2.msapiro.net> proto=SMTP helo=<msapiro.net>
> Oct 12 18:16:23 msapiro postfix/smtpd[26916]: disconnect from msapiro-enet.attlocal.net[10.211.115.100] helo=1 mail=1 rcpt=2 data=1 quit=1 commands=6
> Oct 12 18:16:28 msapiro MailScanner[2489]: New Batch: Scanning 1 messages, 1123 bytes
> Oct 12 18:16:28 msapiro MailScanner[2489]: Virus and Content Scanning: Starting
> Oct 12 18:16:30 msapiro MailScanner[2489]: Requeue: ED750235E9.AA31F to 2207A34012D
> Oct 12 18:16:30 msapiro postfix/smtpd[26916]: connect from localhost[127.0.0.1]
> Oct 12 18:16:30 msapiro postfix/smtpd[26916]: 63BC1340122: client=localhost[127.0.0.1]
> Oct 12 18:16:30 msapiro postfix/cleanup[26921]: 63BC1340122: message-id=<20181013011623.7002C340121 at msapiro.net>
> Oct 12 18:16:30 msapiro postfix/qmgr[2472]: 63BC1340122: from=<mark at msapiro.net>, size=1635, nrcpt=1 (queue active)
> Oct 12 18:16:30 msapiro postfix/smtpd[26916]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 commands=4
> Oct 12 18:16:30 msapiro MailScanner[2489]: Uninfected: Delivered 1 messages
> Oct 12 18:16:30 msapiro postfix/local[26969]: 63BC1340122: to=<mark at msapiro.net>, relay=local, delay=0.13, delays=0.08/0.01/0/0.04, dsn=2.0.0, status=sent (delivered to mailbox)
> Oct 12 18:16:30 msapiro postfix/qmgr[2472]: 63BC1340122: removed
> Oct 12 18:16:30 msapiro MailScanner[2489]: Deleted 1 messages from processing-database

You will see this entry on the incoming message

> Oct 12 18:16:23 msapiro postfix/smtpd[26916]: disconnect from msapiro-enet.attlocal.net[10.211.115.100] helo=1 mail=1 rcpt=2 data=1 quit=1 commands=6

has two rcpt commands, but this

> Oct 12 18:16:30 msapiro postfix/smtpd[26916]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 commands=4

has only one. The original two rcpts were mark at msapiro.net (local) and
mark at ms2.msapiro.net (remote) and apparently when the milter reinjected
the scanned message the only rcpt was mark at msapiro.net.

I did another test where both rcpts were local, mark at msapiro.net and
root at msapiro.net with the same result.

I did a third and fourth test where I reversed the order of the rcpt
commands in the initial submission and the result is the ultimate
delivery is only to the first rcpt in the initial submission whether or
not that recipient is local or remote.

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan