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 |
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 |
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. |
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.) |
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. |
Free forum by Nabble | Edit this page |