I have upgraded my postfix 3.6 to postfix 3.7.0 as well as having upgraded my macOS on which postfix runs from 10.4 (Mojave) to 12 (Monterey)
I have the following problem. postfix is running as expected, but at some point it becomes inoperable on port 25 listening for incoming connections. Using a telnet connection to port 25 just gives no reply and times out. There are no error messages that I see. The last entry in postfix.log is: Mar 03 21:56:23 mail postfix/postscreen[56506]: CONNECT from [112.152.206.91]:21680 to [192.168.2.66]:25 Mar 03 21:56:23 mail postfix/dnsblog[56507]: addr 112.152.206.91 listed by domain zen.spamhaus.org as 127.255.255.254 Mar 03 21:56:29 mail postfix/postscreen[56506]: PASS NEW [112.152.206.91]:21680 Mar 03 21:56:30 mail smtp/smtpd[56511]: connect from unknown[112.152.206.91] Mar 03 21:56:30 mail smtp/smtpd[56511]: NOQUEUE: reject: RCPT from unknown[112.152.206.91]: 450 4.7.1 Client host rejected: cannot find your reverse hostname, [112.152.206.91]; from=<t...@fantasia.com.cn> to=<gerben_wie...@rna.nl> proto=ESMTP helo=<[112.152.206.91]> Mar 03 21:56:31 mail smtp/smtpd[56511]: lost connection after DATA from unknown[112.152.206.91] Mar 03 21:56:31 mail smtp/smtpd[56511]: disconnect from unknown[112.152.206.91] ehlo=1 mail=1 rcpt=0/1 data=0/1 commands=2/4 Mar 03 21:59:51 mail postfix/anvil[56513]: statistics: max connection rate 1/60s for (smtpd:141.98.10.58) at Mar 3 21:56:09 Mar 03 21:59:51 mail postfix/anvil[56513]: statistics: max connection count 1 for (smtpd:141.98.10.58) at Mar 3 21:56:09 Mar 03 21:59:51 mail postfix/anvil[56513]: statistics: max cache size 2 at Mar 3 21:56:30 After that, nothing until I stop and start postfix again. Mar 04 11:05:18 mail postfix[72387]: Postfix is using backwards-compatible default settings Mar 04 11:05:18 mail postfix[72387]: See http://www.postfix.org/COMPATIBILITY_README.html for details Mar 04 11:05:18 mail postfix[72387]: To disable backwards compatibility use "postconf compatibility_level=3.6" and "postfix reload" Mar 04 11:05:18 mail /postfix-script[72394]: stopping the Postfix mail system Mar 04 11:05:19 mail postfix[72401]: Postfix is using backwards-compatible default settings Mar 04 11:05:19 mail postfix[72401]: See http://www.postfix.org/COMPATIBILITY_README.html for details Mar 04 11:05:19 mail postfix[72401]: To disable backwards compatibility use "postconf compatibility_level=3.6" and "postfix reload" Mar 04 11:05:20 mail postfix/postsuper[72443]: warning: bogus file name: maildrop/.turd_postfix Mar 04 11:05:20 mail /postfix-script[72458]: warning: not owned by _postfix: /opt/local/var/lib/postfix/./.turd_postfix Mar 04 11:05:20 mail /postfix-script[72464]: warning: not owned by _postfix: /opt/local/var/spool/postfix/public/.turd_postfix Mar 04 11:05:20 mail /postfix-script[72473]: warning: /opt/local/var/spool/postfix/etc/services and /etc/services differ Mar 04 11:05:20 mail /postfix-script[72475]: starting the Postfix mail system Mar 04 11:05:20 mail postfix/master[72477]: daemon started -- version 3.7.0, configuration /opt/local/etc/postfix There was a comparable hole in the log and a not working postfix before when also mail waas not being received (that was the first time I noticed, so it is now twice and not some sort of hiccup but a real problem): Mar 03 08:18:56 mail smtp/smtpd[29550]: connect from mail.rspamd.net[135.181.136.158] Mar 03 08:18:56 mail smtp/smtpd[29550]: F357AB40B241: client=mail.rspamd.net[135.181.136.158] Mar 03 08:18:57 mail postfix/cleanup[29552]: F357AB40B241: message-id=<1478821c-5453-25c9-e8a8-acf0339e3945@mez onplus.ru> Mar 03 08:18:58 mail smtp/smtpd[29550]: disconnect from mail.rspamd.net[135.181.136.158] ehlo=2 starttls=1 mail =1 rcpt=1 data=1 quit=1 commands=7 Mar 03 08:18:58 mail postfix/qmgr[35300]: F357AB40B241: from=<users-boun...@lists.rspamd.com>, size=6024, nrcpt =1 (queue active) Mar 03 08:18:58 mail postfix/local[29555]: F357AB40B241: passing <ger...@albus.rna.nl> to transport=lmtp Mar 03 08:18:58 mail postfix/lmtp[29556]: F357AB40B241: to=<ger...@albus.rna.nl>, orig_to=<gerben.wie...@rna.nl >, relay=mail.rna.nl[private/dovecot-lmtp], delay=1.4, delays=1.4/0/0/0.01, >dsn=2.0.0, status=sent (250 2.0.0 < ger...@albus.rna.nl> +AhSFuJrIGJ1cwAAnjsRrA Saved) Mar 03 08:18:58 mail postfix/qmgr[35300]: F357AB40B241: removed Mar 03 08:22:18 mail postfix/anvil[29427]: statistics: max connection rate 1/60s for (smtpd:69.72.43.246) at Ma r 3 08:12:47 Mar 03 08:22:18 mail postfix/anvil[29427]: statistics: max connection count 1 for (smtpd:69.72.43.246) at Mar 3 08:12:47 Mar 03 08:22:18 mail postfix/anvil[29427]: statistics: max cache size 3 at Mar 3 08:14:50 Mar 03 11:43:30 mail submission/smtpd[34023]: warning: hostname hosted-by.rootlayer.net does not resolve to add ress 185.222.58.109 Mar 03 11:43:30 mail submission/smtpd[34023]: connect from unknown[185.222.58.109] Mar 03 11:43:30 mail submission/smtpd[34023]: lost connection after EHLO from unknown[185.222.58.109] Mar 03 11:43:30 mail submission/smtpd[34023]: disconnect from unknown[185.222.58.109] ehlo=1 auth=0/1 commands= 1/2 Mar 03 11:43:30 mail submission/smtpd[34023]: warning: hostname hosted-by.rootlayer.net does not resolve to address 185.222.58.109 That last one seems to be some sort of attack on the submission port. I do some geoblocking at pf and afw level, but this one is coming from inside my own country (The Netherlands) so that doesn’t help here. Then there is a period that outgoing mail is still working (the submission attack proceeds), but nothing comes in (so port 25 is probably already dead). Mar 03 11:43:33 mail submission/smtpd[34023]: connect from unknown[185.222.58.109] Mar 03 11:43:33 mail submission/smtpd[34023]: warning: Connection rate limit exceeded: 31 from unknown[185.222. 58.109] for service submission Mar 03 11:43:33 mail submission/smtpd[34023]: disconnect from unknown[185.222.58.109] commands=0/0 Mar 03 11:46:53 mail postfix/anvil[34026]: statistics: max connection rate 31/60s for (submission:185.222.58.10 9) at Mar 3 11:43:33 Mar 03 11:46:53 mail postfix/anvil[34026]: statistics: max connection count 1 for (submission:185.222.58.109) a t Mar 3 11:43:30 Mar 03 11:46:53 mail postfix/anvil[34026]: statistics: max cache size 1 at Mar 3 11:43:30 Mar 03 12:30:28 mail submission/smtpd[35009]: connect from hermione.rna.nl[192.168.2.86] Submission still works, but no connection is accepted on port 25. Around 13:45 I find out about the problem (becoming suspicious that no new mail has arrived for a while) and restart postfix and everything works again. Note, there is some system-level firewalling going on: both pf and afw. Postfix depends on dovecot for authentication, but I don’t think that is triggered on port 25 (haven’t seen it attempted). After a restart of only postfix everything works again, so it does seem that I have isolated the problem to postfix. MacPorts installed: postfix @3.7.0_0+dovecot_sasl+pcre+smtputf8+tls What is the best way to hunt down why postfix stops working on port 25 (that is: no more postfix/postscreen gets started) at some moment? What kind of debugging/logging should I turn on to try to find out what happens? Gerben Wierda (LinkedIn <https://www.linkedin.com/in/gerbenwierda>) R&A IT Strategy <https://ea.rna.nl/> (main site) Book: Chess and the Art of Enterprise Architecture <https://ea.rna.nl/the-book/> Book: Mastering ArchiMate <https://ea.rna.nl/the-book-edition-iii/>
