Home / server / Questions / 1168370
Accepted
Mike
Asked: 2024-12-02 02:28:17 +0800 CST

Postfix and Dovecot refuse to acquire IPs on startup (but later do)

  • 772

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.

networking

2 Answers

  1. Best Answer

    I also now noticed that there is a tiny line of kernel log saying kernel: ... Link is Up - 1Gbps/Full that is after the Postfix boot. However, I'm not sure if the interface is really not yet up before that,

    Well, your output definitely shows enp5s0: <NO-CARRIER> (I think that corresponds to the absence of <RUNNING> in ifconfig) at that point, meaning that the interface is administratively up (OS made it available for use) but operationally down (the physical link is not established).

    That in itself wouldn't prevent its addresses from being bound to (it's the administrative state that matters for that), however, it also causes your IPv6 addresses to be stuck in the tentative state – this flag indicates that they're still pending Duplicate Address Detection (mandatory in IPv6) – and until the addresses clear DAD (and lose the 'tentative' flag) they are not available for use.

    So whatever you have in your networking.service is just slapping the addresses onto the interface but isn't actually waiting for that configuration to become "complete". Keep in mind that by default network-online.target is empty and it's up to you (or perhaps your distro I guess) to put some "waiting" services there; e.g. NetworkManager brings its own helper .service that hooks into network-online.target, systemd-network brings its own, and similarly Debian's ifupdown (aka networking.service) also brings its own ifupdown-wait-online.service which you'd need to enable.

    • 3

  2. I'm marking @grawity's answer as correct, because those hints pointed me in the right direction to look for a solution.

    Additionally, I'll post as an answer the steps I did to solve the problem, since it may be useful for someone else:

    Since I'm using Debian, that particular solution is Debian-specific, and in particular systemd-specific. Other distros may have other tools and configuration settings, but the general idea should be applicable.

    As mentioned in the comments above, systemd has two separate targets - network.target and network-online.target. The first is reached when all network interfaces have been configured (as defined in /etc/network/interfaces or wherever your settings are). As grawity explained in his answer, that means that at this point the network is usable programmatically, but not physically (at least not via IPv6).

    The second target, network-online.target is supposed to be reached when the network is actually really usable. This target depends on a service named ifupdown-wait-online.service which should probe the network and hang/wait until it is really online. After that the network-online.target is reached, and all other services that depend on it, are started by systemd. Dovecot and Postfix do indeed by default depend on network-online.target, so why do they fail?

    Turns out, the ifupdown-wait-online.service has a few configuration settings, defined in /etc/default/networking. One of the settings there is WAIT_ONLINE_METHOD which tells it how exactly it should check if the network is online. Among the options are pinging the gateway or some other predefined host, etc. Guess what the default setting for this option is? To check if the network interfaces are configured.

    This means that with the default settings the ifupdown-wait-online.service is basically a no-op. It only checks if the network is configured, which at this point it always is (unless there was an error).

    After setting WAIT_ONLINE_METHOD to ping6 at letting it ping a well-known host on the network, the boot sequence now works like a charm. At first glance you don't see much of a difference in the boot logs, unless you look at the timestamps: There is a 2 second delay before the kernel reports Link is up, and yet another 2 second delay before ifupdown-wait-online.service finishes. Those couple seconds are all that matters.

    Dec 01 22:30:00 systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups.
Dec 01 22:30:02 kernel: r8169 0000:05:00.0 enp5s0: Link is Up - 1Gbps/Full - flow control rx/tx
Dec 01 22:30:04 systemd[1]: Finished ifupdown-wait-online.service - Wait for network to be configured by ifupdown.
Dec 01 22:30:04 systemd[1]: Reached target network-online.target - Network is Online.
Dec 01 22:30:04 systemd[1]: Starting dovecot.service - Dovecot IMAP/POP3 email server...
Dec 01 22:30:04 systemd[1]: Starting [email protected] - Postfix Mail Transport Agent (instance -)...
Dec 01 22:30:04 systemd[1]: Started dovecot.service - Dovecot IMAP/POP3 email server.
Dec 01 22:30:04 postmulti[1155]: postfix/postlog: starting the Postfix mail system
Dec 01 22:30:04 systemd[1]: Started [email protected] - Postfix Mail Transport Agent (instance -).

    Thanks a lot to @grawity for the valuable pointers!

    • 1