FreeBSD socket.test FAIL: recvmsg() error EAGAIN on accept TCP socket receive

This is a multi-part message in MIME format.
--------------MtidpPEoWnnQ8xRB0CLT5IRR
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: quoted-printable

Greetings,

chrony 4.7 and 4.8 (and possibly others) have an issue with=20
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=20
accept()ed sockets for TCP between FreeBSD and, say, Linux, or with=20
something that a syscall tracer will cause to be retried.


$ truss test/unit/socket.test

=3D> passes

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

$ test/unit/socket.test

=3D> prints Testing socket =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0FAIL (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=20
> message from 127.0.0.1:57724 fd=3D3 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Sent message=20
> to 127.0.0.1:57724 fd=3D3 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:1648:(SCK_Receive) Received data=
=20
> fd=3D4 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened=20
> UDPv4 socket fd=3D3 local=3D127.0.0.1:28164
> 2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened=20
> UDPv4 socket fd=3D4 remote=3D127.0.0.1:28164
> 2025-08-27T14:39:14Z D:../../socket.c:1674:(SCK_Send) Sent data fd=3D4=
=20
> len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Received=20
> message from 127.0.0.1:39243 fd=3D3 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Sent message=20
> to 127.0.0.1:39243 fd=3D3 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:1648:(SCK_Receive) Received data=
=20
> fd=3D4 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened=20
> UDPv4 socket fd=3D3 local=3D127.0.0.1:41555
> 2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened=20
> UDPv4 socket fd=3D4 remote=3D127.0.0.1:41555
> 2025-08-27T14:39:14Z D:../../socket.c:1674:(SCK_Send) Sent data fd=3D4=
=20
> len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Received=20
> message from 127.0.0.1:19472 fd=3D3 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Sent message=20
> to 127.0.0.1:19472 fd=3D3 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:1648:(SCK_Receive) Received data=
=20
> fd=3D4 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened=20
> TCPv4 socket fd=3D3 local=3D127.0.0.1:6992
> 2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened=20
> TCPv4 socket fd=3D4 remote=3D127.0.0.1:6992
> 2025-08-27T14:39:14Z D:../../socket.c:1674:(SCK_Send) Sent data fd=3D4=
=20
> len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Received=20
> message fd=3D5 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:813:(log_message) Sent message=20
> fd=3D5 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:1648:(SCK_Receive) Received data=
=20
> fd=3D4 len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened=20
> TCPv4 socket fd=3D3 local=3D127.0.0.1:27407
> 2025-08-27T14:39:14Z D:../../socket.c:595:(open_ip_socket) Opened=20
> TCPv4 socket fd=3D4 remote=3D127.0.0.1:27407 local=3D127.0.0.1:17334
> 2025-08-27T14:39:14Z D:../../socket.c:1674:(SCK_Send) Sent data fd=3D4=
=20
> len=3D16
> 2025-08-27T14:39:14Z D:../../socket.c:752:(handle_recv_error) Could=20
> not receive message fd=3D5 : Resource temporarily unavailable
> FAIL (on line 75)
>

Debugging this, SCK_AcceptConnection unconditionally sets O_NONBLOCK on=20
the socket,
and recvmsg() (FreeBSD offers recvmmsg() but chrony doesn't use it, see=20
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=20
recvmmsg() - have there been bug reports at the time or fixes? Have we=20
retried this on 13.5, 14.2, 14.3? What do we need to look for?


Cheers,
Matthias

--------------MtidpPEoWnnQ8xRB0CLT5IRR
Content-Type: text/html; charset=UTF-8
Content-Transfer-Encoding: quoted-printable

<!DOCTYPE html>
<html>
  <head>

    <meta http-equiv=3D"content-type" content=3D"text/html; charset=3DUTF-=
8">
  </head>
  <body>
    <p>Greetings,</p>
    <p>chrony 4.7 and 4.8 (and possibly others) have an issue with
      test/util/socket.c's self test,<br>
      UNLESS running under "truss" (think strace in the Linux world).</p>
    <p>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.<br>
    </p>
    <p><br>
    </p>
    <p>$ truss test/unit/socket.test <br>
    </p>
    <p>=3D&gt; passes</p>
    <p>
      <blockquote type=3D"cite">
        <span style=3D"font-family:monospace"><span
            style=3D"color:#000000;background-color:#ffffff;">close(3)</sp=
an><span
            style=3D"color:#000000;background-color:#ffffff;">
            =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0</span><span
            style=3D"color:#000000;background-color:#ffffff;">=C2=A0=3D 0 =
(0x0)</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">close(4)=
</span><span
            style=3D"color:#000000;background-color:#ffffff;">
            =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0</span><span
            style=3D"color:#000000;background-color:#ffffff;">=C2=A0=3D 0 =
(0x0)</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">PASS</sp=
an><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">write(1,=
"PASS\n",5)</span><span
            style=3D"color:#000000;background-color:#ffffff;">
            =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0</span><span
            style=3D"color:#000000;background-color:#ffffff;">=C2=A0=3D 5 =
(0x5)</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">exit(0x0=
)</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">process
            exit, rval =3D 0</span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
        </span>
      </blockquote>
      <br>
    </p>
    <p>$ test/unit/socket.test</p>
    <p>=3D&gt; prints <span style=3D"font-family:monospace"><span
          style=3D"color:#000000;background-color:#ffffff;">Testing socket
          =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0FAIL (on line 75)</span><br>
        <span style=3D"color:#000000;background-color:#ffffff;">
        </span><br>
      </span>
      FAIL (on line 75).</p>
    <p><br>
    </p>
    <p>Building with debug enabled and -d on the command line yields:</p>
    <p>...</p>
    <p>
      <blockquote type=3D"cite">
        <span style=3D"font-family:monospace"><span
            style=3D"color:#000000;background-color:#ffffff;">2025-08-27T1=
4:39:14Z
            D:../../socket.c:813:(log_message) Received message from
            127.0.0.1:57724 fd=3D3 len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:813:(log_message) Sent message to
            127.0.0.1:57724 fd=3D3 len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:1648:(SCK_Receive) Received data fd=3D4
            len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:595:(open_ip_socket) Opened UDPv4 socket
            fd=3D3 local=3D127.0.0.1:28164</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:595:(open_ip_socket) Opened UDPv4 socket
            fd=3D4 remote=3D127.0.0.1:28164</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:1674:(SCK_Send) Sent data fd=3D4 len=3D16</sp=
an><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:813:(log_message) Received message from
            127.0.0.1:39243 fd=3D3 len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:813:(log_message) Sent message to
            127.0.0.1:39243 fd=3D3 len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:1648:(SCK_Receive) Received data fd=3D4
            len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:595:(open_ip_socket) Opened UDPv4 socket
            fd=3D3 local=3D127.0.0.1:41555</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:595:(open_ip_socket) Opened UDPv4 socket
            fd=3D4 remote=3D127.0.0.1:41555</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:1674:(SCK_Send) Sent data fd=3D4 len=3D16</sp=
an><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:813:(log_message) Received message from
            127.0.0.1:19472 fd=3D3 len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:813:(log_message) Sent message to
            127.0.0.1:19472 fd=3D3 len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:1648:(SCK_Receive) Received data fd=3D4
            len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:595:(open_ip_socket) Opened TCPv4 socket
            fd=3D3 local=3D127.0.0.1:6992</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:595:(open_ip_socket) Opened TCPv4 socket
            fd=3D4 remote=3D127.0.0.1:6992</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:1674:(SCK_Send) Sent data fd=3D4 len=3D16</sp=
an><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:813:(log_message) Received message fd=3D5
            len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:813:(log_message) Sent message fd=3D5 len=3D1=
6</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:1648:(SCK_Receive) Received data fd=3D4
            len=3D16</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:595:(open_ip_socket) Opened TCPv4 socket
            fd=3D3 local=3D127.0.0.1:27407</span><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:595:(open_ip_socket) Opened TCPv4 socket
            fd=3D4 remote=3D127.0.0.1:27407 local=3D127.0.0.1:17334</span>=
<span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:1674:(SCK_Send) Sent data fd=3D4 len=3D16</sp=
an><span
            style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">2025-08-=
27T14:39:14Z
            D:../../socket.c:752:(handle_recv_error) Could not receive
            message fd=3D5 : Resource temporarily unavailable</span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">
          </span></span>
        <span style=3D"font-family:monospace"><span
            style=3D"color:#000000;background-color:#ffffff;">FAIL (on
            line 75)</span><br>
          <span style=3D"color:#000000;background-color:#ffffff;">
          </span><br>
        </span>
      </blockquote>
      <br>
    </p>
    <p>Debugging this, SCK_AcceptConnection unconditionally sets
      O_NONBLOCK on the socket, <br>
      and recvmsg() (FreeBSD offers recvmmsg() but chrony doesn't use
      it, see below) "Resource temporarily unavailable" is EAGAIN.</p>
    <p>I will disable the socket.c unit test on FreeBSD port for the
      time being.</p>
    <p><br>
    </p>
    <p>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?<br>
    </p>
    <p><br>
    </p>
    <p>Cheers,<br>
      Matthias<br>
    </p>
  </body>
</html>

--------------MtidpPEoWnnQ8xRB0CLT5IRR--

-- 
To unsubscribe email chrony-users-request-kWFZVVI9zxvPqho9SqqRMmD2FQJk+8+b@public.gmane.org 
with "unsubscribe" in the subject.
For help email chrony-users-request-kWFZVVI9zxvPqho9SqqRMmD2FQJk+8+b@public.gmane.org 
with "help" in the subject.
Trouble?  Email [email protected]