Milter rejection logged twice by Postfix

[David Bürgin]

I’m running a milter that may perform rejection (SMFIS_REJECT) at the
milter HELO stage. This condition appears in the system log as follows:

Jan 04 13:50:07 mail postfix/smtpd[149922]: connect from unknown[156.0.64.217]
Jan 04 13:50:07 mail spf-milter[147333]: mail.mydomain.org (helo): fail
Jan 04 13:50:07 mail spf-milter[147333]: rejected message from sender "mail.mydomain.org"
Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: HELO from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; proto=SMTP helo=<mail.mydomain.org>
Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: MAIL from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; from=<> proto=SMTP helo=<mail.mydomain.org>
Jan 04 13:50:08 mail postfix/smtpd[149922]: lost connection after MAIL from unknown[156.0.64.217]
Jan 04 13:50:08 mail postfix/smtpd[149922]: disconnect from unknown[156.0.64.217] helo=1 mail=0/1 commands=1/2

• Why does Postfix log ‘milter-reject’ twice?
• Why does it also log milter rejection for the MAIL stage, when the
  client was rejected already at the HELO stage?

Thank you.


--
David

[Wietse Venema]

David B?rgin:
> I?m running a milter that may perform rejection (SMFIS_REJECT) at the
> milter HELO stage. This condition appears in the system log as follows:
>
> Jan 04 13:50:07 mail postfix/smtpd[149922]: connect from unknown[156.0.64.217]
> Jan 04 13:50:07 mail spf-milter[147333]: mail.mydomain.org (helo): fail
> Jan 04 13:50:07 mail spf-milter[147333]: rejected message from sender "mail.mydomain.org"
> Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: HELO from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; proto=SMTP helo=<mail.mydomain.org>

The remote SMTP client sent EHLO (or HELO). The Milter rejected the
command with "550 5.7.23 SPF...". Postfix logged the response and
replied to the remote SMTP client.

> Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: MAIL from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; from=<> proto=SMTP helo=<mail.mydomain.org>

The remote SMTP client sent MAIL FROM. Postfix reused the last
Milter "reject", logged the response, and replied to the remote
SMTP client.

So the real question is "Why did the client not disconnect after
receiving a 550 EHLO reponse?". Servers aren't supposed to disconnect
after replying with 550.

        Wietse

[David Bürgin]

Me:

> I’m running a milter that may perform rejection (SMFIS_REJECT) at the
> milter HELO stage. This condition appears in the system log as follows:
>
> Jan 04 13:50:07 mail postfix/smtpd[149922]: connect from unknown[156.0.64.217]
> Jan 04 13:50:07 mail spf-milter[147333]: mail.mydomain.org (helo): fail
> Jan 04 13:50:07 mail spf-milter[147333]: rejected message from sender "mail.mydomain.org"
> Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: HELO from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; proto=SMTP helo=<mail.mydomain.org>
> Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: MAIL from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; from=<> proto=SMTP helo=<mail.mydomain.org>
> Jan 04 13:50:08 mail postfix/smtpd[149922]: lost connection after MAIL from unknown[156.0.64.217]
> Jan 04 13:50:08 mail postfix/smtpd[149922]: disconnect from unknown[156.0.64.217] helo=1 mail=0/1 commands=1/2
>
> • Why does Postfix log ‘milter-reject’ twice?
> • Why does it also log milter rejection for the MAIL stage, when the
>   client was rejected already at the HELO stage?

Perhaps it’s related to this?
http://www.postfix.org/SMTPD_ACCESS_README.html#timing

Apparently, the rejection is not performed immediately after the EHLO
command. During testing I notice that Postfix still proceeds to the MAIL
command, even though the milter requested rejection.

[David Bürgin]

Wietse Venema:

> David B?rgin:
>> I?m running a milter that may perform rejection (SMFIS_REJECT) at the
>> milter HELO stage. This condition appears in the system log as follows:
>>
>> Jan 04 13:50:07 mail postfix/smtpd[149922]: connect from unknown[156.0.64.217]
>> Jan 04 13:50:07 mail spf-milter[147333]: mail.mydomain.org (helo): fail
>> Jan 04 13:50:07 mail spf-milter[147333]: rejected message from sender "mail.mydomain.org"
>> Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: HELO from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; proto=SMTP helo=<mail.mydomain.org>
>
> The remote SMTP client sent EHLO (or HELO). The Milter rejected the
> command with "550 5.7.23 SPF...". Postfix logged the response and
> replied to the remote SMTP client.
>
>> Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: MAIL from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; from=<> proto=SMTP helo=<mail.mydomain.org>
>
> The remote SMTP client sent MAIL FROM. Postfix reused the last
> Milter "reject", logged the response, and replied to the remote
> SMTP client.
>
> So the real question is "Why did the client not disconnect after
> receiving a 550 EHLO reponse?". Servers aren't supposed to disconnect
> after replying with 550.

I see – thank you! (Saw your answer only after posting my follow-up.)

[Wietse Venema]

David B?rgin:

> Me:
> > I?m running a milter that may perform rejection (SMFIS_REJECT) at the
> > milter HELO stage. This condition appears in the system log as follows:
> >
> > Jan 04 13:50:07 mail postfix/smtpd[149922]: connect from unknown[156.0.64.217]
> > Jan 04 13:50:07 mail spf-milter[147333]: mail.mydomain.org (helo): fail
> > Jan 04 13:50:07 mail spf-milter[147333]: rejected message from sender "mail.mydomain.org"
> > Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: HELO from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; proto=SMTP helo=<mail.mydomain.org>
> > Jan 04 13:50:07 mail postfix/smtpd[149922]: NOQUEUE: milter-reject: MAIL from unknown[156.0.64.217]: 550 5.7.23 SPF validation failed; from=<> proto=SMTP helo=<mail.mydomain.org>
> > Jan 04 13:50:08 mail postfix/smtpd[149922]: lost connection after MAIL from unknown[156.0.64.217]
> > Jan 04 13:50:08 mail postfix/smtpd[149922]: disconnect from unknown[156.0.64.217] helo=1 mail=0/1 commands=1/2
> >
> > ? Why does Postfix log ?milter-reject? twice?
> > ? Why does it also log milter rejection for the MAIL stage, when the
> >   client was rejected already at the HELO stage?
>
> Perhaps it?s related to this?
> http://www.postfix.org/SMTPD_ACCESS_README.html#timing

Nope.
As documented Milters are not affected by smtpd_delay_reject settings.
As documented smtpd_delay_reject affects smtpd_mumble_restrictions.

In the logging:

    milter-reject: HELO from unknown[156.0.64.217]: 550 5.7.23 SPF
    validation failed

That is the response to the HELO command, as in

    client: HELO mail.mydomain.org
    server: 550 5.7.23 SPF validation failed

And a little later:

    client: MAIL FROM:<>
    server: 550 5.7.23 SPF validation failed

        Wietse.