主页 / server / 问题 / 1168370
Accepted
Mike
Asked: 2024-12-02 02:28:17 +0800 CST

Postfix 和 Dovecot 在启动时拒绝获取 IP（但后来获取了）

  • 772

这个问题乍一看似乎不是什么大问题，但事实证明并非如此，而且可能不完全是 Postfix/Dovecot 独有的。如果有人能给我指点一下就太好了……

设置如下：我有一个名称服务器 (BIND)，以及在同一台机器上运行的 Postfix/Dovecot 组合。它有 1 个 IPv4 地址（这些地址很少见...）和多个 IPv6 地址。起初，所有服务器都在所有接口上运行，即监听0.0.0.0和[::]，但后来我决定为它们提供单独的 IPv6（“因为我们可以...”）。在 v4 上，它们仍位于同一 IP 上。

在初始设置和测试期间，一切都运行良好。最后，我决定重新启动机器，以确保没有陈旧/临时的配置潜伏在周围，并且全新启动后一切都按预期运行。

然后发生了以下情况（日志减少到相关部分）：

...
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 -).

请注意，BIND 在所有接口上成功启动。Dovecot 并行启动，并在尝试监听单独的 IPv6 时抛出错误。（日志中没有提到 IPv4 和 localhost，因此要么成功，要么 IPv6 错误先出现。）Postfix 在尝试监听相同的 IPv6 时遇到相同的错误。

现在，问题是，当我通过 启动后手动启动这些服务时systemctl start，它们都可以正常启动。而且它们实际上可以在所有接口上运行。

所以我最初的想法是，在启动过程中存在某种竞争条件，因此在 Dovecot/Postfix 启动之前，并非所有 IPv6 接口都已启动。这应该是不可能的，因为它们都依赖于network-online.target，而根据 systemd 的说法，这在 BIND 开始启动之前就已经完全完成了。

因此我将 Dovecot 切换到与 BIND 相同的 IPv6 (:b00d) 上运行，因为它在该 IP 上成功启动。Postfix 仍位于原始 IP (:d19c)。同时，我还创建了一个虚拟“服务”，该服务在启动过程中仅吐出网络配置，以便我可以看到 Dovecot 和 Postfix 在启动过程中看到的内容。我让此服务运行了两次 - 一次在 BIND/Postfix/Dovecot 之前，一次在之后。

最终结果是：a）即使使用与 BIND 相同的 IP，Dovecot 仍然会失败。b）根据ifconfig实际配置，在服务启动之前所有 IPv6 都已启动（应该如此）

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.

再次，启动后我可以手动启动这两项服务 - 没有错误。

有人知道发生了什么事吗？我在网上找到了一些类似的报告，但它们都有一些原因，在我的案例中可以排除。

谢谢您的反馈！

编辑：将第二个日志替换ip addr为，以ifconfig显示启动时的当前网络配置。我还添加了显示启动后 2 分钟手动启动 Dovecot/Postfix 的行 - 没有错误。

EDIT2：附加 IP 是通过/etc/network/interfaces.d/Debian 中的文件配置的，该文件由 提供/etc/network/interfaces。启动时，这两个文件在启动过程中一步处理networking.service。这是代码片段：

iface enp5s0 inet6 static
  address 2a01:4f8:140:501a::b00d/64

iface enp5s0 inet6 static
  address 2a01:4f8:140:501a::d19c/64

传统上，这些将是别名接口（enp5s0：1，：2等），但现在这些似乎已经过时了，因此上述方法显然是现在配置附加 IP 的首选方式。

networking

2 个回答

  1. Best Answer

    我现在还注意到，在 Postfix 启动后，内核日志中有一小行写着 kernel: ... Link is Up - 1Gbps/Full。但是，我不确定在此之前接口是否真的还没有启动，

    嗯，您的输出肯定显示enp5s0: <NO-CARRIER>（我认为这对应于 ifconfig 中的缺失<RUNNING>）在那时，这意味着接口在管理上处于启动状态（操作系统使其可供使用）但在操作上处于关闭状态（物理链路未建立）。

    这本身并不会阻止其地址被绑定（重要的是管理状态），但是，它也会导致您的 IPv6 地址停留在该tentative状态 - 此标志表示它们仍在等待重复地址检测（IPv6 中强制要求） - 并且直到地址清除 DAD（并丢失“暂定”标志）时，它们才可用。

    因此，无论你在 networking.service 中有什么，都只是将地址贴到接口上，但实际上并没有等待该配置“完成”。请记住，默认情况下它network-online.target是空的，由你（或者可能是你的发行版，我猜）在那里放置一些“等待”服务；例如，NetworkManager 带有自己的辅助 .service，该服务挂接到 network-online.target，systemd-network 带有自己的辅助 .service，同样，Debian 的 ifupdown（又名 networking.service）也带有自己的辅助 .service ifupdown-wait-online.service，你需要启用它。

    • 3

  2. 我将@grawity的答案标记为正确，因为这些提示为我指明了寻找解决方案的正确方向。

    此外，我将发布我解决问题的步骤作为答案，因为它可能对其他人有用：

    由于我使用的是 Debian，因此该特定解决方案是 Debian 专用的，特别是 systemd 专用的。其他发行版可能有其他工具和配置设置，但总体思路应该适用。

    正如上面的评论中提到的，systemd有两个单独的目标 -network.target和。当所有网络接口都已配置（如在或您的设置中定义）network-online.target时，将达到第一个目标。正如grawity在他的回答中解释的那样，这意味着此时网络可以通过编程使用，但不能通过物理方式使用（至少不能通过IPv6使用）。/etc/network/interfaces

    第二个目标，network-online.target应该在网络真正可用时实现ifupdown-wait-online.service。此目标依赖于名为的服务，该服务应探测网络并挂起/等待，直到它真正在线。达到之后network-online.target，所有依赖于它的其他服务都由启动systemd。Dovecot 和 Postfix 确实默认依赖于network-online.target，那么为什么它们会失败呢？

    事实证明，ifupdown-wait-online.service有几个配置设置，定义在 中/etc/default/networking。其中一个设置是WAIT_ONLINE_METHOD告诉它应该如何检查网络是否在线。选项包括 ping 网关或其他预定义主机等。猜猜这个选项的默认设置是什么？检查网络接口是否配置。

    这意味着在默认设置下，这ifupdown-wait-online.service基本上是无操作的。它只检查网络是否已配置，目前它总是已配置（除非出现错误）。

    WAIT_ONLINE_METHOD在将其设置为后，ping6让它 ping 网络上的知名主机，启动顺序现在运行良好。乍一看，除非您查看时间戳，否则启动日志中不会出现太大差异：内核报告之前有 2 秒延迟Link is up，完成之前还有 2 秒延迟ifupdown-wait-online.service。这几秒钟才是最重要的。

    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 -).

    非常感谢@grawity的宝贵指点！

    • 1

相关问题