I have configured Postfix to send all emails to a smart host, and it can work for weeks without problems. But every now and then it stops working and shows messages such as these in the log (the first two lines are for the last successful sending, and the last two are the first message that fails to go out):
Nov 24 20:05:30 nextcloud postfix/smtp[443568]: 3882C1B5D8A: to=<xxxxxx>, relay=relay.grnet.gr[83.212.2.185]:587, delay=2.3, delays=1.3/0/0.02/1, dsn=2.0.0, status=sent (250 OK id=1oyGbJ-0001PM-H2)
Nov 24 20:05:30 nextcloud postfix/qmgr[193834]: 3882C1B5D8A: removed
Nov 24 20:44:43 nextcloud postfix/postfix-script[1563]: warning: symlink leaves directory: /etc/postfix/./makedefs.out
Nov 24 20:44:46 nextcloud postfix/postfix-script[1751]: warning: /var/spool/postfix/etc/resolv.conf and /etc/resolv.conf differ
Nov 24 20:44:46 nextcloud postfix/postfix-script[1772]: starting the Postfix mail system
Nov 24 20:44:46 nextcloud postfix/master[1774]: daemon started -- version 3.4.13, configuration /etc/postfix
Nov 24 21:05:19 nextcloud postfix/smtpd[4252]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
Nov 24 21:05:19 nextcloud postfix/smtpd[4252]: connect from localhost[127.0.0.1]
Nov 24 21:05:19 nextcloud postfix/smtpd[4252]: E76A51B5819: client=localhost[127.0.0.1]
Nov 24 21:05:20 nextcloud postfix/cleanup[4257]: E76A51B5819: message-id=<[email protected]>
Nov 24 21:05:20 nextcloud postfix/smtpd[4252]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Nov 24 21:05:20 nextcloud postfix/qmgr[1776]: E76A51B5819: from=<xxxxxx>, size=37076, nrcpt=1 (queue active)
Nov 24 21:05:21 nextcloud postfix/smtp[4258]: E76A51B5819: to=<xxxxxx>, relay=none, delay=0.36, delays=0.33/0.03/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=relay.grnet.gr type=MX: Host not found, try again)
Subsequently it remains in this status for ever (it was once stuck for about three weeks until I found out); all messages fail and remain in the queue. When I restart it, it works again, sends all the deferred messages, and works happily until the next time the problem occurs.
How can I configure it to be resilient and not require a restart?
The problem originally happened with Postfix 3.4.13 in Ubuntu 20.04, and it still happens with the machine upgraded to Postfix 3.6.4-1ubuntu1.3 on 22.04. Here is /etc/postfix/main.cf:
myorigin = /etc/mailname
biff = no
compatibility_level = 3
relayhost = relay.grnet.gr:587
mynetworks = 127.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128
inet_interfaces = loopback-only
virtual_alias_maps = hash:/etc/postfix/virtual
masquerade_domains = grnet.gr
Edit 2024-03-07
It turns out I've been wrong in some things. The problem was actually that resolv.conf wasn't (or isn't) being properly copied when the machine restarts.
Postfix works chrooted, so it isn't actually using /etc/resolv.conf, but /var/spool/postfix/etc/resolv.conf. Postfix comes with a script that performs some administrative tasks, including copying the system's resolv.conf to the chroot, and it is run at Postfix start time.
What I hadn't noticed was that the problem occurs after machine restart (and I'm not certain it happens always). Apparently the Postfix script that copies resolv.conf runs before the system has had the chance to properly set it up. Subsequently restarting Postfix solves the problem.
There are several reports of this happening, for many different reasons. I don't know the reason in this case yet.
Edit 2024-03-10
I increased syslog timestamp precision and rebooted the system. It turns out that the postfix startup script copies /etc/resolv.conf about half a second before it's ready:
lrwxrwxrwx 1 root root 29 2018-08-24 11:37:47.299687838 +0300 /etc/resolv.conf -> ../run/resolvconf/resolv.conf
-rw-r--r-- 1 root root 328 2024-03-10 13:05:17.268000000 +0200 /run/resolvconf/resolv.conf
-rw-r--r-- 1 root root 0 2024-03-10 13:05:16.756000000 +0200 /var/spool/postfix/etc/resolv.conf
The first trace of Postfix starting in the log is much later:
2024-03-10T13:05:21.516151+02:00 nextcloud postfix[1418]: Postfix is running with backwards-compatible default settings
...
2024-03-10T13:05:38.486795+02:00 nextcloud postfix/postfix-script[1832]: warning: /var/spool/postfix/etc/resolv.conf and /etc/resolv.conf differ
This machine gets its ip address with dhcp, which interestingly seems to happen later than /etc/resolv.conf (at 13:05:17.44). This is probably irrelevant, since resolv.conf tells to use systemd-resolvedon localhost:53.
