Milter rejection logged twice by Postfix

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

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
Reply | Threaded
Open this post in threaded view
|

Re: Milter rejection logged twice by Postfix

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
Reply | Threaded
Open this post in threaded view
|

Re: Milter rejection logged twice by Postfix

David Bürgin
In reply to this post by 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.
Reply | Threaded
Open this post in threaded view
|

Re: Milter rejection logged twice by Postfix

David Bürgin
In reply to this post by Wietse Venema
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.)
Reply | Threaded
Open this post in threaded view
|

Re: Milter rejection logged twice by Postfix

Wietse Venema
In reply to this post by David Bürgin
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.