DevHeads.net

Only logging from a connection when an unrelated error is forced in main.cf

Using postfix 3.4.6 on macOS. Using maillog as syslog is broken on macOS.

The postfix server is running on 192.168.2.66, dovecot and other parts of the mail setup not yet. I am connecting from 192.168.2.67 on port 25, using telnet. I’m issuing an HELO and a VRFY (turned on temporarily in main.cf). I’ve set 192.168.2.67 in the debug_peer_list.

When I introduce an error in main.cf (the file for check_client_access does not exist),

debug_peer_level = 2
debug_peer_list = 192.168.2.67
check_client_access regexp:/opt/local/etc/postfix/error/rna_rbl_whitelist_clients

I see debugging info when I connectusing telnet.

Oct 06 13:16:17 mail /postfix-script[11198]: refreshing the Postfix mail system
Oct 06 13:16:17 mail postfix/master[11129]: reload -- version 3.4.6, configuration /opt/local/etc/postfix
Oct 06 13:16:37 mail postfix/smtpd[11208]: error: open /opt/local/etc/postfix/error/rna_rbl_whitelist_clients: No such file or directory
Oct 06 13:16:40 mail postfix/smtpd[11208]: connect from unknown[192.168.2.67]
Oct 06 13:16:40 mail postfix/smtpd[11208]: smtp_stream_setup: maxtime=300 enable_deadline=0
Oct 06 13:16:40 mail postfix/smtpd[11208]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 127.0.0.0/8
Oct 06 13:16:40 mail postfix/smtpd[11208]: match_hostaddr: smtpd_client_event_limit_exceptions: 192.168.2.67 ~? 127.0.0.0/8
Oct 06 13:16:40 mail postfix/smtpd[11208]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 192.168.2.0/24
Oct 06 13:16:40 mail postfix/smtpd[11208]: match_hostaddr: smtpd_client_event_limit_exceptions: 192.168.2.67 ~? 192.168.2.0/24
Oct 06 13:16:40 mail postfix/smtpd[11208]: report connect to all milters
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter_macro_lookup: "j"
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter_macro_lookup: result "mail.rna.nl"
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter_macro_lookup: "{daemon_name}"
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter_macro_lookup: result "mail.rna.nl"
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter_macro_lookup: "{daemon_addr}"
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter_macro_lookup: result "192.168.2.66"
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter_macro_lookup: "v"
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter_macro_lookup: result "Postfix 3.4.6"
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter8_connect: non-protocol events for protocol version 6:
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter8_connect: transport=unix endpoint=/opt/local/var/run/rspamd/milter.sock
Oct 06 13:16:40 mail postfix/smtpd[11208]: warning: connect to Milter service unix:/opt/local/var/run/rspamd/milter.sock: No such file or directory
Oct 06 13:16:40 mail postfix/smtpd[11208]: milter8_conn_event: skip milter unix:/opt/local/var/run/rspamd/milter.sock
Oct 06 13:16:40 mail postfix/smtpd[11208]: > unknown[192.168.2.67]: 220 mail.rna.nl ESMTP Postfix
Oct 06 13:16:40 mail postfix/smtpd[11208]: watchdog_pat: 0x7fdc9c42ed90
Oct 06 13:17:08 mail postfix/smtpd[11208]: < unknown[192.168.2.67]: quit
Oct 06 13:17:08 mail postfix/smtpd[11208]: > unknown[192.168.2.67]: 221 2.0.0 Bye
Oct 06 13:17:08 mail postfix/smtpd[11208]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 127.0.0.0/8
Oct 06 13:17:08 mail postfix/smtpd[11208]: match_hostaddr: smtpd_client_event_limit_exceptions: 192.168.2.67 ~? 127.0.0.0/8
Oct 06 13:17:08 mail postfix/smtpd[11208]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 192.168.2.0/24
Oct 06 13:17:08 mail postfix/smtpd[11208]: match_hostaddr: smtpd_client_event_limit_exceptions: 192.168.2.67 ~? 192.168.2.0/24
Oct 06 13:17:08 mail postfix/smtpd[11208]: disconnect event to all milters
Oct 06 13:17:08 mail postfix/smtpd[11208]: milter8_disc_event: skip quit milter unix:/opt/local/var/run/rspamd/milter.sock
Oct 06 13:17:08 mail postfix/smtpd[11208]: disconnect from unknown[192.168.2.67] quit=1 commands=1
Oct 06 13:17:08 mail postfix/smtpd[11208]: free all milters
Oct 06 13:17:08 mail postfix/smtpd[11208]: free milter unix:/opt/local/var/run/rspamd/milter.sock
Oct 06 13:17:08 mail postfix/smtpd[11208]: name_mask: no_address_mappings

When I remove the forced error

check_client_access regexp:/opt/local/etc/postfix/rna_rbl_whitelist_clients

I see nothing. No “connect from unknown[192.168.2.67]”. Nothing. This baffles me. Why do I only see logging in my maillog (including debug_peer) when I introduce an unrelated error in main.cf? I’d like to see logging for each mail delivery.

Gerben Wierda
Chess and the Art of Enterprise Architecture <http://enterprisechess.com/>
Mastering ArchiMate <http://masteringarchimate.com/>
Architecture for Real Enterprises <https://www.infoworld.com/blog/architecture-for-real-enterprises/> at InfoWorld
On Slippery Ice <https://eapj.org/on-slippery-ice/> at EAPJ

Comments

Re: Only logging from a connection when an unrelated error is fo

By Wietse Venema at 10/06/2019 - 10:18

Gerben Wierda:
With confiuration error:

# postconf maillog_file debug_peer_list smtpd_client_restrictions
maillog_file = /tmp/log/maillog
debug_peer_list = 127.0.0.1
smtpd_client_restrictions = regexp:/non/existent
# date; telnet 127.0.0.1 25
Sun Oct 6 10:05:53 EDT 2019
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
220 tail.porcupine.org ESMTP Postfix
quit
221 2.0.0 Bye
Connection closed by foreign host.
#

Logfile:
Oct 06 10:04:03 tail postfix/master[2062]: reload -- version 3.5-20190922, configuration /etc/postfix
Oct 06 10:05:53 tail postfix/smtpd[2518]: error: open /non/existent: No such file or directory
Oct 06 10:05:53 tail postfix/smtpd[2518]: connect from localhost[127.0.0.1]
Oct 06 10:05:53 tail postfix/smtpd[2518]: smtp_stream_setup: maxtime=300 enable_deadline=0
Oct 06 10:05:53 tail postfix/smtpd[2518]: > localhost[127.0.0.1]: 220 tail.porcupine.org ESMTP Postfix
...
Oct 06 10:05:58 tail postfix/smtpd[2518]: < localhost[127.0.0.1]: quit
Oct 06 10:05:58 tail postfix/smtpd[2518]: > localhost[127.0.0.1]: 221 2.0.0 Bye
Oct 06 10:05:58 tail postfix/smtpd[2518]: disconnect from localhost[127.0.0.1] quit=1 commands=1

After removing the configuration error:

# postconf maillog_file debug_peer_list smtpd_client_restrictions
maillog_file = /tmp/log/maillog
debug_peer_list = 127.0.0.1
smtpd_client_restrictions =
# date; telnet 127.0.0.1 25
Sun Oct 6 10:08:18 EDT 2019
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
220 tail.porcupine.org ESMTP Postfix
quit
221 2.0.0 Bye
Connection closed by foreign host.
#

Logfile:
Oct 06 10:08:02 tail postfix/master[2062]: reload -- version 3.5-20190922, configuration /etc/postfix
Oct 06 10:08:18 tail postfix/smtpd[2545]: connect from localhost[127.0.0.1]
Oct 06 10:08:18 tail postfix/smtpd[2545]: smtp_stream_setup: maxtime=300 enable_deadline=0
Oct 06 10:08:18 tail postfix/smtpd[2545]: > localhost[127.0.0.1]: 220 tail.porcupine.org ESMTP Postfix
...
Oct 06 10:08:20 tail postfix/smtpd[2545]: < localhost[127.0.0.1]: quit
Oct 06 10:08:20 tail postfix/smtpd[2545]: > localhost[127.0.0.1]: 221 2.0.0 Bye
Oct 06 10:08:20 tail postfix/smtpd[2545]: disconnect from localhost[127.0.0.1] quit=1 commands=1

In other words, this still works as intended. Code changes since
Postfix 3.4.5 are totally unrelated to error handling or logging.

Wietse

Wietse