#1059700 opensmtpd dies with "pony express: smtpd: bind: Cannot assign requested address"

Package:
opensmtpd
Source:
opensmtpd
Description:
secure, reliable, lean, and easy-to configure SMTP server
Submitter:
Harald Dunkel
Date:
2024-01-02 10:51:05 UTC
Severity:
normal
#1059700#5
Date:
2023-12-30 12:31:02 UTC
From:
To:
opensmtpd is not started by systemd at boot time. Error message
is:

dex06:~# journalctl -b -u opensmtpd
Dec 30 12:57:38 dex06.hosting2.aixigo.de systemd[1]: Starting opensmtpd.service - OpenSMTPD SMTP server...
Dec 30 12:57:38 dex06.hosting2.aixigo.de opensmtpd[103]: Active Internet connections (only servers)
Dec 30 12:57:38 dex06.hosting2.aixigo.de opensmtpd[103]: Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
Dec 30 12:57:38 dex06.hosting2.aixigo.de opensmtpd[103]: tcp6       0      0 :::3142                 :::*                    LISTEN      -
Dec 30 12:57:38 dex06.hosting2.aixigo.de smtpd[111]: info: OpenSMTPD 6.8.0p2 starting
Dec 30 12:57:38 dex06.hosting2.aixigo.de systemd[1]: Started opensmtpd.service - OpenSMTPD SMTP server.
Dec 30 12:57:38 dex06.hosting2.aixigo.de smtpd[130]: pony express: smtpd: bind: Cannot assign requested address
Dec 30 12:57:38 dex06.hosting2.aixigo.de smtpd[126]: smtpd: process pony socket closed
Dec 30 12:57:38 dex06.hosting2.aixigo.de systemd[1]: opensmtpd.service: Main process exited, code=exited, status=1/FAILURE
Dec 30 12:57:38 dex06.hosting2.aixigo.de systemd[1]: opensmtpd.service: Failed with result 'exit-code'.


If I manually restart opensmtpd, there is no such problem. As
you can see in the logfile, another service (apt-cacher-ng)
doesn't have this problem. (I had modified opensmtpd.service
to do a netstat -tnlp in ExecStartPre.)

smtpd.conf is

	listen on lo
	action "relay" relay host smtp://smarthost
	match from local for any action "relay"

Please tell *which* address it cannot bind.


Regards

Harri

#1059700#10
Date:
2023-12-30 15:26:05 UTC
From:
To:
Hi Harald,
bind, but I see that that's no longer the case on 7.4.0p1. It may still
work on your version.

I forwarded this bug upstream three years ago:
https://github.com/OpenSMTPD/OpenSMTPD/issues/1106

Duplicating the /etc/hosts entry no longer causes the bug to appear on
7.4.0p1. If it's not too much hassle, would you be willing to try
7.4.0p1 from Debian backports and let me know if you can still reproduce
this bug? It would at least help us narrow down if it's since been fixed
upstream.

Happy new year,
Ryan

#1059700#15
Date:
2024-01-02 10:43:11 UTC
From:
To:
Hi Ryan,

dex07:~# journalctl -b -u opensmtpd
Jan 02 11:30:43 dex07.example.com systemd[1]: Starting opensmtpd.service - OpenSMTPD SMTP server...
Jan 02 11:30:43 dex07.example.com smtpd[105]: info: OpenSMTPD 7.4.0-portable starting
Jan 02 11:30:44 dex07.example.com smtpd[144]: dispatcher: smtpd: bind: Cannot assign requested address
Jan 02 11:30:44 dex07.example.com smtpd[137]: smtpd: process dispatcher socket closed
Jan 02 11:30:44 dex07.example.com systemd[1]: opensmtpd.service: Deactivated successfully.
Jan 02 11:30:44 dex07.example.com systemd[1]: Started opensmtpd.service - OpenSMTPD SMTP server.

strace shows

:
144   socket(AF_INET, SOCK_STREAM, IPPROTO_IP <unfinished ...>
137   rt_sigaction(SIGTERM, {sa_handler=0x7fa9bd612180, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fa9bd42ffd0},  <unfinished ...>
144   <... socket resumed>)             = 13
137   <... rt_sigaction resumed>{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
144   setsockopt(13, SOL_SOCKET, SO_REUSEADDR, [1], 4 <unfinished ...>
137   rt_sigaction(SIGCHLD, {sa_handler=0x7fa9bd612180, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fa9bd42ffd0},  <unfinished ...>
144   <... setsockopt resumed>)         = 0
137   <... rt_sigaction resumed>{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
144   bind(13, {sa_family=AF_INET, sin_port=htons(25), sin_addr=inet_addr("10.150.1.33")}, 16 <unfinished ...>
137   rt_sigaction(SIGHUP, {sa_handler=0x7fa9bd612180, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fa9bd42ffd0},  <unfinished ...>
144   <... bind resumed>)               = 0
137   <... rt_sigaction resumed>{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
144   socket(AF_INET6, SOCK_STREAM, IPPROTO_IP <unfinished ...>
137   rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fa9bd42ffd0},  <unfinished ...>
144   <... socket resumed>)             = 14
137   <... rt_sigaction resumed>{sa_handler=SIG_IGN, sa_mask=[], sa_flags=0}, 8) = 0
144   setsockopt(14, SOL_SOCKET, SO_REUSEADDR, [1], 4 <unfinished ...>
137   epoll_ctl(6, EPOLL_CTL_ADD, 8, {events=EPOLLIN, data={u32=8, u64=8}} <unfinished ...>
144   <... setsockopt resumed>)         = 0
137   <... epoll_ctl resumed>)          = 0
144   setsockopt(14, SOL_IPV6, IPV6_V6ONLY, [1], 4 <unfinished ...>
137   epoll_ctl(6, EPOLL_CTL_ADD, 9, {events=EPOLLIN, data={u32=9, u64=9}} <unfinished ...>
144   <... setsockopt resumed>)         = 0
137   <... epoll_ctl resumed>)          = 0
144   bind(14, {sa_family=AF_INET6, sin6_port=htons(25), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "2001:db8:36e:1::21", &sin6_addr), sin6_scope_id=0}, 28 <unfinished ...>
137   epoll_ctl(6, EPOLL_CTL_ADD, 11, {events=EPOLLIN, data={u32=11, u64=11}} <unfinished ...>
144   <... bind resumed>)               = -1 EADDRNOTAVAIL (Cannot assign requested address)
137   <... epoll_ctl resumed>)          = 0
:

ie it could bind to the IPv4 address, but not IPv6.


BTW, smtpd.conf is

table lan { 10.150.0.0/16, 2001:db8:36e::/48 }
table example { "example.de", "example.com" }

listen on lo
listen on eth0
listen on eth1

action "relay" relay host smtp://mailhost.ac.example.de

match from local for any action "relay"
match from src <lan> for domain <example> action "relay"


Regards

Harri