[chrony-users] FreeBSD socket.test FAIL: recvmsg() error EAGAIN on accept TCP socket receive

[ Thread Index | Date Index | More chrony.tuxfamily.org/chrony-users Archives ]

Greetings,

chrony 4.7 and 4.8 (and possibly others) have an issue with test/util/socket.c's self test,
UNLESS running under "truss" (think strace in the Linux world).

Apparently we're looking at OS-specific differences WRT non-blocking accept()ed sockets for TCP between FreeBSD and, say, Linux, or with something that a syscall tracer will cause to be retried.


$ truss test/unit/socket.test

=> passes

close(3)                                         = 0 (0x0)
close(4)                                         = 0 (0x0)
PASS
write(1,"PASS\n",5)                              = 5 (0x5)
exit(0x0)
process exit, rval = 0

$ test/unit/socket.test

=> prints Testing socket                         FAIL (on line 75)

 FAIL (on line 75).


Building with debug enabled and -d on the command line yields:

...

2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Received message from 127.0.0.1:57724 fd=3 len=16
2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Sent message to 127.0.0.1:57724 fd=3 len=16
2025-08-27T14:39:14Z D:../../socket.c:1648:(SCK_Receive) Received data fd=4 len=16
2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened UDPv4 socket fd=3 local=127.0.0.1:28164
2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened UDPv4 socket fd=4 remote=127.0.0.1:28164
2025-08-27T14:39:14Z D:../../socket.c:1674:(SCK_Send) Sent data fd=4 len=16
2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Received message from 127.0.0.1:39243 fd=3 len=16
2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Sent message to 127.0.0.1:39243 fd=3 len=16
2025-08-27T14:39:14Z D:../../socket.c:1648:(SCK_Receive) Received data fd=4 len=16
2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened UDPv4 socket fd=3 local=127.0.0.1:41555
2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened UDPv4 socket fd=4 remote=127.0.0.1:41555
2025-08-27T14:39:14Z D:../../socket.c:1674:(SCK_Send) Sent data fd=4 len=16
2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Received message from 127.0.0.1:19472 fd=3 len=16
2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Sent message to 127.0.0.1:19472 fd=3 len=16
2025-08-27T14:39:14Z D:../../socket.c:1648:(SCK_Receive) Received data fd=4 len=16
2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened TCPv4 socket fd=3 local=127.0.0.1:6992
2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened TCPv4 socket fd=4 remote=127.0.0.1:6992
2025-08-27T14:39:14Z D:../../socket.c:1674:(SCK_Send) Sent data fd=4 len=16
2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Received message fd=5 len=16
2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Sent message fd=5 len=16
2025-08-27T14:39:14Z D:../../socket.c:1648:(SCK_Receive) Received data fd=4 len=16
2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened TCPv4 socket fd=3 local=127.0.0.1:27407
2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened TCPv4 socket fd=4 remote=127.0.0.1:27407 local=127.0.0.1:17334
2025-08-27T14:39:14Z D:../../socket.c:1674:(SCK_Send) Sent data fd=4 len=16
2025-08-27T14:39:14Z D:../../socket.c:752:(handle_recv_error) Could not receive message fd=5 : Resource temporarily unavailable
 FAIL (on line 75)

Debugging this, SCK_AcceptConnection unconditionally sets O_NONBLOCK on the socket,
and recvmsg() (FreeBSD offers recvmmsg() but chrony doesn't use it, see below) "Resource temporarily unavailable" is EAGAIN.

I will disable the socket.c unit test on FreeBSD port for the time being.


Speaking of which, configure states that FreeBSD 11.0 had a broken recvmmsg() - have there been bug reports at the time or fixes? Have we retried this on 13.5, 14.2, 14.3? What do we need to look for?


Cheers,
Matthias


Mail converted by MHonArc 2.6.19+ http://listengine.tuxfamily.org/