Início / server / Perguntas / 1168370
Accepted
Mike
Asked: 2024-12-02 02:28:17 +0800 CST

Postfix e Dovecot se recusam a adquirir IPs na inicialização (mas o fazem depois)

  • 772

Este problema parece trivial a princípio, mas não é, e provavelmente não é totalmente específico do Postfix/Dovecot. Seria ótimo se alguém pudesse me dar uma dica...

A configuração é a seguinte: Tenho um servidor de nomes (BIND) e um combo Postfix/Dovecot rodando na mesma máquina. Ele tem 1 endereço IPv4 (esses são escassos...) e vários endereços IPv6. No começo, todos os servidores estavam rodando em todas as interfaces, ou seja, escutando em 0.0.0.0e [::], mas então decidi dar a eles IPv6 separados ("porque podemos..."). Na v4 eles permanecem no mesmo IP.

Durante a configuração inicial e os testes, tudo funcionou bem. No final, decidi reiniciar a máquina só para ter certeza de que não há nenhuma configuração obsoleta/temporária à espreita e que tudo funciona como esperado após uma inicialização limpa.

E então aconteceu o seguinte (registro reduzido às partes relevantes):

...
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 que o BIND inicia com sucesso em todas as interfaces. O Dovecot inicia em paralelo e gera um erro ao tentar escutar em um IPv6 separado. (O log não diz nada sobre IPv4 e localhost, então ou funciona, ou o erro IPv6 vem primeiro.) O Postfix encontra o mesmo erro ao tentar escutar no mesmo IPv6.

Agora, a questão é que, quando eu inicio esses serviços manualmente após a inicialização via systemctl start, ambos inicializam sem problemas. E eles realmente funcionam em todas as interfaces.

Então meu pensamento inicial foi que há algum tipo de condição de corrida durante o processo de inicialização, de modo que nem todas as interfaces IPv6 são realmente ativadas, antes do início do Dovecot/Postfix. O que não deveria ser possível, já que todas elas dependem de network-online.target, que de acordo com o systemd é totalmente concluído antes do BIND iniciar a inicialização.

Então eu troquei o Dovecot para rodar no mesmo IPv6 (:b00d) que o BIND, já que ele inicializa com sucesso naquele IP. O Postfix ainda está no IP original (:d19c). Ao mesmo tempo, eu também criei um "serviço" fictício que apenas exibe a configuração de rede durante o processo de inicialização, para que eu possa ver o que o Dovecot e o Postfix estão vendo durante a inicialização. Eu fiz esse serviço rodar duas vezes - uma antes do BIND/Postfix/Dovecot, e uma depois.

O resultado final é: a) O Dovecot ainda falha mesmo quando se usa o mesmo IP do BIND . b) de acordo com ifconfigtodos os IPv6s que estão realmente configurados e ativos antes do início dos serviços (como deveria ser)

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.

Novamente, após a inicialização, posso iniciar ambos os serviços manualmente - sem erros.

Alguém tem alguma ideia do que está acontecendo? Encontrei alguns relatos semelhantes na internet, mas todos eles têm causas que podem ser descartadas no meu caso.

Obrigado por qualquer feedback!

EDIT : Substitua o segundo log onde ip addré usado em vez de ifconfigpara mostrar a configuração de rede atual durante o tempo de inicialização. Também incluí as linhas que mostram o início manual do Dovecot/Postfix 2 minutos após a inicialização - sem erros.

EDIT2: Os IPs adicionais são configurados por meio de um arquivo sob /etc/network/interfaces.d/o qual no Debian é originado por /etc/network/interfaces. Ambos os arquivos são processados ​​em uma etapa durante a inicialização quando networking.serviceé iniciado. Este é o snippet:

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

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

Tradicionalmente, essas seriam interfaces com alias (enp5s0:1, :2, etc.), mas elas parecem estar obsoletas agora, então a maneira acima é aparentemente a preferida para configurar IPs adicionais atualmente.

networking

2 respostas

  1. Best Answer

    Também notei agora que há uma pequena linha de log do kernel dizendo kernel: ... Link is Up - 1Gbps/Full que é depois da inicialização do Postfix. No entanto, não tenho certeza se a interface realmente não está ativa antes disso,

    Bem, sua saída definitivamente mostra enp5s0: <NO-CARRIER>(acho que isso corresponde à ausência de <RUNNING>em ifconfig) naquele ponto, o que significa que a interface está administrativamente ativa (o sistema operacional a disponibilizou para uso), mas operacionalmente inativa (o link físico não foi estabelecido).

    Isso por si só não impediria que seus endereços fossem vinculados (é o estado administrativo que importa para isso), no entanto, também faz com que seus endereços IPv6 fiquem presos no tentativeestado — esse sinalizador indica que eles ainda estão pendentes de Detecção de Endereço Duplicado (obrigatório no IPv6) — e até que os endereços limpem o DAD (e percam o sinalizador "tentativo"), eles não estarão disponíveis para uso.

    Então, o que quer que você tenha em seu networking.service está apenas colocando os endereços na interface, mas não está realmente esperando que essa configuração fique "completa". Tenha em mente que, por padrão, network-online.targetestá vazio e cabe a você (ou talvez sua distro, eu acho) colocar alguns serviços "em espera" lá; por exemplo, o NetworkManager traz seu próprio helper .service que se conecta ao network-online.target, o systemd-network traz o seu próprio, e similarmente o ifupdown do Debian (também conhecido como networking.service) também traz o seu próprio ifupdown-wait-online.serviceque você precisa habilitar.

    • 3

  2. Estou marcando a resposta de @grawity como correta, porque essas dicas me indicaram a direção certa para procurar uma solução.

    Além disso, postarei como resposta os passos que segui para resolver o problema, pois pode ser útil para outra pessoa:

    Como estou usando o Debian, essa solução em particular é específica do Debian, e em particular específica do systemd. Outras distros podem ter outras ferramentas e definições de configuração, mas a ideia geral deve ser aplicável.

    Conforme mencionado nos comentários acima, systemdtem dois alvos separados - network.targete network-online.target. O primeiro é alcançado quando todas as interfaces de rede foram configuradas (conforme definido em /etc/network/interfacesou onde quer que suas configurações estejam). Como grawity explicou em sua resposta, isso significa que neste ponto a rede é utilizável programaticamente, mas não fisicamente (pelo menos não via IPv6).

    O segundo alvo, supostamente, network-online.targetdeve ser alcançado quando a rede estiver realmente utilizável. Este alvo depende de um serviço chamado ifupdown-wait-online.serviceque deve sondar a rede e travar/esperar até que esteja realmente online. Depois disso, o network-online.targeté alcançado, e todos os outros serviços que dependem dele são iniciados por systemd. Dovecot e Postfix de fato dependem por padrão de network-online.target, então por que eles falham?

    Acontece que o ifupdown-wait-online.servicetem algumas configurações, definidas em /etc/default/networking. Uma das configurações lá é WAIT_ONLINE_METHODque diz exatamente como ele deve verificar se a rede está online. Entre as opções estão pingando o gateway ou algum outro host predefinido, etc. Adivinhe qual é a configuração padrão para essa opção? Para verificar se as interfaces de rede estão configuradas .

    Isso significa que com as configurações padrão, o ifupdown-wait-online.serviceé basicamente um no-op. Ele só verifica se a rede está configurada, o que neste ponto sempre está (a menos que tenha ocorrido um erro).

    Após definir WAIT_ONLINE_METHODpara ping6at permitindo que ele faça ping em um host bem conhecido na rede, a sequência de inicialização agora funciona perfeitamente. À primeira vista, você não vê muita diferença nos logs de inicialização, a menos que olhe os timestamps: há um atraso de 2 segundos antes do kernel reportar Link is up, e ainda outro atraso de 2 segundos antes de ifupdown-wait-online.serviceterminar. Esses dois segundos são tudo o que importa.

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

    Muito obrigado ao @grawity pelas dicas valiosas!

    • 1

relate perguntas