This issue looks trivial at first, but turns out it's not, and probably not entirely Postfix/Dovecot specific. Would be great if someone can give me a pointer...
The setup is as follows: I have a nameserver (BIND), and a Postfix/Dovecot combo running on the same machine. It has 1 IPv4 address (those are scarce...) and multiple IPv6 addresses. At first, all servers were running on all interfaces, i.e. listening on 0.0.0.0
and [::]
, but then I decided to give them separate IPv6 ("because we can..."). On v4 they remain on the same IP.
During the initial setup and testing, everything worked fine. At the end, I decided to reboot the machine just to be sure that there is no stale/temporary configuration lurking around and everything runs as expected after a fresh boot.
And then following happened (log reduced to relevant parts):
...
Nov 30 22:49:52 systemd[1]: Finished networking.service - Raise network interfaces.
Nov 30 22:49:52 systemd[1]: Reached target network.target - Network.
Nov 30 22:49:52 systemd[1]: Reached target network-online.target - Network is Online.
Nov 30 22:49:52 systemd[1]: Starting dovecot.service - Dovecot IMAP/POP3 email server...
Nov 30 22:49:52 systemd[1]: Starting named.service - BIND Domain Name Server...
Nov 30 22:49:52 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
Nov 30 22:49:52 named[984]: starting BIND 9.20.2-1-Debian (Stable Release) <id:>
Nov 30 22:49:52 named[984]: running on Linux x86_64 6.11.5-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.11.5-1 (2024-10-27)
...
Nov 30 22:49:52 named[984]: listening on IPv4 interface lo, 127.0.0.6#53
Nov 30 22:49:52 named[984]: listening on IPv4 interface enp5s0, 88.198.70.58#53
Nov 30 22:49:52 named[984]: listening on IPv6 interface enp5s0, 2a01:4f8:140:501a::b00d#53
...
Nov 30 22:49:52 dovecot[983]: Error: bind(2a01:4f8:140:501a::d19c, 587) failed: Cannot assign requested address
Nov 30 22:49:52 dovecot[983]: Error: service(submission-login): listen(2a01:4f8:140:501a::d19c, 587) failed: Cannot assign requested address
Nov 30 22:49:52 dovecot[983]: Error: bind(2a01:4f8:140:501a::d19c, 143) failed: Cannot assign requested address
Nov 30 22:49:52 dovecot[983]: Error: service(imap-login): listen(2a01:4f8:140:501a::d19c, 143) failed: Cannot assign requested address
Nov 30 22:49:52 dovecot[983]: Error: bind(2a01:4f8:140:501a::d19c, 993) failed: Cannot assign requested address
Nov 30 22:49:52 dovecot[983]: Error: service(imap-login): listen(2a01:4f8:140:501a::d19c, 993) failed: Cannot assign requested address
Nov 30 22:49:52 dovecot[983]: Fatal: Failed to start listeners
Nov 30 22:49:52 systemd[1]: dovecot.service: Main process exited, code=exited, status=89/n/a
Nov 30 22:49:52 systemd[1]: dovecot.service: Failed with result 'exit-code'.
Nov 30 22:49:52 systemd[1]: Failed to start dovecot.service - Dovecot IMAP/POP3 email server.
...
Nov 30 22:49:52 systemd[1]: Started named.service - BIND Domain Name Server.
Nov 30 22:49:52 systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups.
Nov 30 22:49:52 systemd[1]: Starting [email protected] - Postfix Mail Transport Agent (instance -)...
Nov 30 22:49:52 postmulti[1141]: postfix/postlog: starting the Postfix mail system
Nov 30 22:49:52 postfix/master[1143]: fatal: bind 2a01:4f8:140:501a::d19c port 25: Cannot assign requested address
Nov 30 22:49:54 postmulti[1145]: postfix/postlog: fatal: mail system startup failed
Nov 30 22:49:55 systemd[1]: [email protected]: Control process exited, code=exited, status=1/FAILURE
Nov 30 22:49:55 systemd[1]: [email protected]: Failed with result 'exit-code'.
Nov 30 22:49:55 systemd[1]: Failed to start [email protected] - Postfix Mail Transport Agent (instance -).
Note that BIND starts successfully on all interfaces. Dovecot starts in parallel and spits an error trying to listen on a separate IPv6. (The log says nothing about IPv4 and localhost, so it either works, or the IPv6 error comes first.) The Postfix runs into the same error trying to listen on the same IPv6.
Now, the thing is, when I start those services manually after the boot via systemctl start
, they both boot without issues. And they actually work on all interfaces.
So my initial thought was that there is some kind of a race condition during the boot process, so that not all IPv6 interfaces are actually brought up, before Dovecot/Postfix start. Which should not be possible, since they all depend on network-online.target
, which according to systemd is fully completed before BIND starts booting.
So I switched Dovecot to run on the same IPv6 (:b00d) as BIND, since it boots successfully on that IP. Postfix is still at the original IP (:d19c). At the same time I also created a dummy "service" that just spits out the network configuration during the boot process, so that I can see what Dovecot and Postfix are seeing during bootup. I made this service run twice - once before BIND/Postfix/Dovecot, and once after.
End result is:
a) Dovecot still fails even when using the same IP as BIND.
b) according to ifconfig
all IPv6s are actually configured and up before the services start (as it should be)
Dec 01 19:52:16 systemd[1]: Finished networking.service - Raise network interfaces.
Dec 01 19:52:16 systemd[1]: Reached target network.target - Network.
Dec 01 19:52:16 systemd[1]: Reached target network-online.target - Network is Online.
Dec 01 19:52:16 systemd[1]: Starting named.service - BIND Domain Name Server...
Dec 01 19:52:16 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
Dec 01 19:52:16 systemd[1]: Reached target getty.target - Login Prompts.
Dec 01 19:52:16 named[981]: starting BIND 9.20.2-1-Debian (Stable Release) <id:>
Dec 01 19:52:16 named[981]: running on Linux x86_64 6.11.5-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.11.5-1 (2024-10-27)
...
Dec 01 19:52:16 named[981]: listening on IPv4 interface lo, 127.0.0.6#53
Dec 01 19:52:16 named[981]: listening on IPv4 interface enp5s0, 88.198.70.58#53
Dec 01 19:52:16 named[981]: listening on IPv6 interface enp5s0, 2a01:4f8:140:501a::b00d#53
...
Dec 01 19:52:16 systemd[1]: Started named.service - BIND Domain Name Server.
Dec 01 19:52:16 systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups.
Dec 01 19:52:16 systemd[1]: Starting dovecot.service - Dovecot IMAP/POP3 email server...
Dec 01 19:52:16 systemd[1]: Starting test-networking.service - ###################### Test Network Configuration ###########################...
Dec 01 19:52:16 ip[992]: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
Dec 01 19:52:16 ip[992]: link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
Dec 01 19:52:16 ip[992]: inet 127.0.0.1/8 scope host lo
Dec 01 19:52:16 ip[992]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[992]: inet 127.0.0.3/8 brd 127.0.0.0 scope host secondary lo
Dec 01 19:52:16 ip[992]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[992]: inet 127.0.0.6/8 brd 127.0.0.0 scope host secondary lo
Dec 01 19:52:16 ip[992]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[992]: inet6 ::1/128 scope host noprefixroute
Dec 01 19:52:16 ip[992]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[992]: 2: enp5s0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc fq_codel state DOWN group default qlen 1000
Dec 01 19:52:16 ip[992]: link/ether a8:a1:59:08:49:5d brd ff:ff:ff:ff:ff:ff
Dec 01 19:52:16 ip[992]: inet 88.198.70.58/27 brd 88.198.70.63 scope global enp5s0
Dec 01 19:52:16 ip[992]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[992]: inet6 2a01:4f8:140:501a::d19c/64 scope global tentative
Dec 01 19:52:16 ip[992]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[992]: inet6 2a01:4f8:140:501a::b00d/64 scope global tentative
Dec 01 19:52:16 ip[992]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[992]: inet6 2a01:4f8:140:501a::2/64 scope global tentative
Dec 01 19:52:16 ip[992]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 systemd[1]: test-networking.service: Deactivated successfully.
Dec 01 19:52:16 systemd[1]: Finished test-networking.service - ###################### Test Network Configuration ###########################.
Dec 01 19:52:16 dovecot[991]: Error: bind(2a01:4f8:140:501a::d19c, 587) failed: Cannot assign requested address
Dec 01 19:52:16 dovecot[991]: Error: service(submission-login): listen(2a01:4f8:140:501a::d19c, 587) failed: Cannot assign requested address
Dec 01 19:52:16 dovecot[991]: Error: bind(2a01:4f8:140:501a::d19c, 143) failed: Cannot assign requested address
Dec 01 19:52:16 dovecot[991]: Error: service(imap-login): listen(2a01:4f8:140:501a::d19c, 143) failed: Cannot assign requested address
Dec 01 19:52:16 dovecot[991]: Error: bind(2a01:4f8:140:501a::d19c, 993) failed: Cannot assign requested address
Dec 01 19:52:16 dovecot[991]: Error: service(imap-login): listen(2a01:4f8:140:501a::d19c, 993) failed: Cannot assign requested address
Dec 01 19:52:16 dovecot[991]: Fatal: Failed to start listeners
Dec 01 19:52:16 systemd[1]: dovecot.service: Main process exited, code=exited, status=89/n/a
Dec 01 19:52:16 systemd[1]: dovecot.service: Failed with result 'exit-code'.
Dec 01 19:52:16 systemd[1]: Failed to start dovecot.service - Dovecot IMAP/POP3 email server.
Dec 01 19:52:16 systemd[1]: Reached target multi-user.target - Multi-User System.
Dec 01 19:52:16 systemd[1]: Reached target graphical.target - Graphical Interface.
Dec 01 19:52:16 systemd[1]: Starting [email protected] - Postfix Mail Transport Agent (instance -)...
Dec 01 19:52:16 systemd[1]: Starting test-networking2.service - ********************** Second Test Network Configuration ****************************...
Dec 01 19:52:16 ip[998]: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
Dec 01 19:52:16 ip[998]: link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
Dec 01 19:52:16 ip[998]: inet 127.0.0.1/8 scope host lo
Dec 01 19:52:16 ip[998]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[998]: inet 127.0.0.3/8 brd 127.0.0.0 scope host secondary lo
Dec 01 19:52:16 ip[998]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[998]: inet 127.0.0.6/8 brd 127.0.0.0 scope host secondary lo
Dec 01 19:52:16 ip[998]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[998]: inet6 ::1/128 scope host noprefixroute
Dec 01 19:52:16 ip[998]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[998]: 2: enp5s0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc fq_codel state DOWN group default qlen 1000
Dec 01 19:52:16 ip[998]: link/ether a8:a1:59:08:49:5d brd ff:ff:ff:ff:ff:ff
Dec 01 19:52:16 ip[998]: inet 88.198.70.58/27 brd 88.198.70.63 scope global enp5s0
Dec 01 19:52:16 ip[998]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[998]: inet6 2a01:4f8:140:501a::d19c/64 scope global tentative
Dec 01 19:52:16 ip[998]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[998]: inet6 2a01:4f8:140:501a::b00d/64 scope global tentative
Dec 01 19:52:16 ip[998]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 ip[998]: inet6 2a01:4f8:140:501a::2/64 scope global tentative
Dec 01 19:52:16 ip[998]: valid_lft forever preferred_lft forever
Dec 01 19:52:16 systemd[1]: test-networking2.service: Deactivated successfully.
Dec 01 19:52:16 systemd[1]: Finished test-networking2.service - ********************** Second Test Network Configuration ****************************.
Dec 01 19:52:17 postmulti[1143]: postfix/postlog: starting the Postfix mail system
Dec 01 19:52:17 postfix/master[1145]: fatal: bind 2a01:4f8:140:501a::d19c port 25: Cannot assign requested address
Dec 01 19:52:19 kernel: r8169 0000:05:00.0 enp5s0: Link is Up - 1Gbps/Full - flow control rx/tx
Dec 01 19:52:19 postmulti[1146]: postfix/postlog: fatal: mail system startup failed
Dec 01 19:52:20 systemd[1]: [email protected]: Control process exited, code=exited, status=1/FAILURE
Dec 01 19:52:20 systemd[1]: [email protected]: Failed with result 'exit-code'.
Dec 01 19:52:20 systemd[1]: Failed to start [email protected] - Postfix Mail Transport Agent (instance -).
Dec 01 19:52:20 systemd[1]: Startup finished in 3.180s (kernel) + 6.272s (userspace) = 9.453s.
...
Dec 01 19:54:04 systemd[1]: Starting dovecot.service - Dovecot IMAP/POP3 email server...
Dec 01 19:54:04 systemd[1]: Started dovecot.service - Dovecot IMAP/POP3 email server.
Dec 01 19:54:10 systemd[1]: Starting [email protected] - Postfix Mail Transport Agent (instance -)...
Dec 01 19:54:10 postmulti[1341]: postfix/postlog: warning: symlink leaves directory: /etc/postfix/./postfix-files
Dec 01 19:54:10 postmulti[1375]: postfix/postlog: starting the Postfix mail system
Dec 01 19:54:10 systemd[1]: Started [email protected] - Postfix Mail Transport Agent (instance -).
Dec 01 19:54:10 systemd[1]: Starting postfix.service - Postfix Mail Transport Agent...
Dec 01 19:54:10 systemd[1]: Finished postfix.service - Postfix Mail Transport Agent.
Again, after booting I can start both services manually - no errors.
Does anyone have a clue what's going on? I found a few similar reports on the internet, but they all have causes that can be ruled out in my case.
Thanks for any feedback!
EDIT: Replace the second log where ip addr
is used instead of ifconfig
to show the current network configuration during boot time.
I also included the lines that show the manual start of Dovecot/Postfix 2 minutes after the boot - no errors.
EDIT2: The additional IPs are configured via a file under /etc/network/interfaces.d/
which in Debian is sourced by /etc/network/interfaces
. Both files are processed in one step during boot when networking.service
is started. This is the snippet:
iface enp5s0 inet6 static
address 2a01:4f8:140:501a::b00d/64
iface enp5s0 inet6 static
address 2a01:4f8:140:501a::d19c/64
Traditionally, these would have been aliased interfaces (enp5s0:1, :2, etc.) but these seem to be obsolete now, so the above is apparently the preferred way to configure additional IPs nowadays.