Bug accepting timed-out connections with IPv6 (C#)

bernardnormier commented 3 weeks ago

An object adapter in the Holding state keeps accepting connections by does not read them and does not send a ValidateConnection message until it's back in the Active state.

With this test: https://github.com/zeroc-ice/ice/compare/main...bernardnormier:connect-holding?expand=1

a client attempts to establish two connections to an OA in the Holding state
both attempts fail with a ConnectTimeoutException (as expected)
when the OA is back in the Active State, it's expected to send & fail to send ValidateConnection message for the two failed attempts, and then accept new connections
- this works fine with IPv4, but not with IPv6

Furthermore, with IPv6, the server never shuts down (waitForShutdown never returns), because "_handler.pending" never reaches 0.

Partial server logging with comments for IPv4 (expected behavior):

-- 8/24/2024 12:28:36:754 server: Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 53
   request id = 2
   identity = controller
   facet = 
   operation = resumeAdapter
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 8/24/2024 12:28:36:755 server: Network: accepting tcp connections at 127.0.0.1:12010
-- 8/24/2024 12:28:36:755 server: Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 2
   reply status = 0 (ok)
   encoding = 1.1
-- 8/24/2024 12:28:36:755 server: Network: trying to accept tcp connection
   local address = 127.0.0.1:12010
   remote address = 127.0.0.1:55400
-- 8/24/2024 12:28:36:755 server: Protocol: sending validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 8/24/2024 12:28:36:762 server: Network: trying to accept tcp connection
   local address = 127.0.0.1:12010
   remote address = 127.0.0.1:55401
-- 8/24/2024 12:28:36:762 server: Protocol: sending validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 8/24/2024 12:28:36:776 server: Network: closed tcp connection
   local address = 127.0.0.1:12010
   remote address = 127.0.0.1:55400   <== expected, first client connection attempt that timed out
   Ice.ConnectionLostException: Exception of type 'Ice.ConnectionLostException' was thrown.
    ---> System.Net.Sockets.SocketException (32): Broken pipe
      at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
      at Ice.Internal.StreamSocket.write(ByteBuffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 434
      --- End of inner exception stack trace ---
      at Ice.Internal.StreamSocket.write(ByteBuffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 452
      at Ice.Internal.StreamSocket.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 175
      at Ice.Internal.TcpTransceiver.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/TcpTransceiver.cs:line 48
      at Ice.Internal.IdleTimeoutTransceiverDecorator.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/IdleTimeoutTransceiverDecorator.cs:line 94
      at Ice.ConnectionI.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 2727
      at Ice.ConnectionI.validate(Int32 operation) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 1860
      at Ice.ConnectionI.start(StartCallback callback) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 33
-- 8/24/2024 12:28:36:777 server: Network: closed tcp connection
   local address = 127.0.0.1:12010
   remote address = 127.0.0.1:55401 <== expected, second client connection attempt that timed out
   Ice.ConnectionLostException: Exception of type 'Ice.ConnectionLostException' was thrown.
    ---> System.Net.Sockets.SocketException (32): Broken pipe
      at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
      at Ice.Internal.StreamSocket.write(ByteBuffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 434
      --- End of inner exception stack trace ---
      at Ice.Internal.StreamSocket.write(ByteBuffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 452
      at Ice.Internal.StreamSocket.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 175
      at Ice.Internal.TcpTransceiver.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/TcpTransceiver.cs:line 48
      at Ice.Internal.IdleTimeoutTransceiverDecorator.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/IdleTimeoutTransceiverDecorator.cs:line 94
      at Ice.ConnectionI.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 2727
      at Ice.ConnectionI.validate(Int32 operation) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 1860
      at Ice.ConnectionI.start(StartCallback callback) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 33
-- 8/24/2024 12:28:37:760 server: Network: trying to accept tcp connection
   local address = 127.0.0.1:12010
   remote address = 127.0.0.1:55402   
-- 8/24/2024 12:28:37:761 server: Protocol: sending validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 8/24/2024 12:28:37:761 server: Network: accepted tcp connection
   local address = 127.0.0.1:12010
   remote address = 127.0.0.1:55402 <== third attempt succeeds (expected)
-- 8/24/2024 12:28:37:762 server: Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 39
   request id = 1
   identity = timeout
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 8/24/2024 12:28:37:763 server: Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 1
   reply status = 0 (ok)
   encoding = 1.1

Partial server logging with comments for IPv6 (unexpected behavior):

-- 8/24/2024 12:25:48:238 server: Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 53
   request id = 2
   identity = controller
   facet = 
   operation = resumeAdapter
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 8/24/2024 12:25:48:239 server: Network: accepting tcp connections at ::1:12010
-- 8/24/2024 12:25:48:239 server: Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 2
   reply status = 0 (ok)
   encoding = 1.1
-- 8/24/2024 12:25:48:239 server: Network: trying to accept tcp connection
   local address = ::1:12010
   remote address = ::1:55384    <== first attempt from client while OA was holding
-- 8/24/2024 12:25:48:239 server: Protocol: sending validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 8/24/2024 12:25:48:255 server: Network: closed tcp connection
   local address = ::1:12010
   remote address = ::1:55384
   Ice.ConnectionLostException: Exception of type 'Ice.ConnectionLostException' was thrown. <== expected since client gave up
    ---> System.Net.Sockets.SocketException (32): Broken pipe
      at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
      at Ice.Internal.StreamSocket.write(ByteBuffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 434
      --- End of inner exception stack trace ---
      at Ice.Internal.StreamSocket.write(ByteBuffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 452
      at Ice.Internal.StreamSocket.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/StreamSocket.cs:line 175
      at Ice.Internal.TcpTransceiver.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/TcpTransceiver.cs:line 48
      at Ice.Internal.IdleTimeoutTransceiverDecorator.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/Internal/IdleTimeoutTransceiverDecorator.cs:line 94
      at Ice.ConnectionI.write(Buffer buf) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 2727
      at Ice.ConnectionI.validate(Int32 operation) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 1860
      at Ice.ConnectionI.start(StartCallback callback) in /Users/bernard/builds/ice/csharp/src/Ice/ConnectionI.cs:line 33
-- 8/24/2024 12:25:50:264 server: Protocol: received request  <== 2 seconds later, server didn't accept/process any other incoming connection
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 48
   request id = 3
   identity = controller
   facet = 
   operation = shutdown
   mode = 0 (normal)
   context = 
   encoding = 1.1

(All on macos)

pepone commented 2 weeks ago

I have been debugging this for a while, for IPv6 case I see

2 startAccept exception: System.ArgumentException: The supplied System.Net.SocketAddress is an invalid size for the System.Net.IPEndPoint end point. (Parameter 'socketAddress')
   at System.Net.IPEndPoint.Create(SocketAddress socketAddress)
   at System.Net.Sockets.SocketAsyncEventArgs.FinishOperationAccept(SocketAddress remoteSocketAddress)
   at System.Net.Sockets.SocketAsyncEventArgs.FinishOperationSyncSuccess(Int32 bytesTransferred, SocketFlags flags)
   at System.Net.Sockets.SocketAsyncEventArgs.FinishOperationSync(SocketError socketError, Int32 bytesTransferred, SocketFlags flags)
   at System.Net.Sockets.SocketAsyncEventArgs.DoOperationAccept(Socket _, SafeSocketHandle handle, SafeSocketHandle acceptHandle, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AcceptAsync(SocketAsyncEventArgs e, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.AcceptAsync(Socket socket, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AcceptAsync(Socket acceptSocket, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AcceptAsync()
   at System.Net.Sockets.Socket.BeginAccept(AsyncCallback callback, Object state)
   at Ice.Internal.TcpAcceptor.startAccept(AsyncCallback callback, Object state) in /Users/jose/Documents/3.8/connect-holding/csharp/src/Ice/Internal/TcpAcceptor.cs:line 49

Here startAsyncs from TcpAcceptor is throwing an ArgumentException, but the connection factory only handles Ice.LocalException.

try
{
    if (_acceptor.startAccept(completedCallback, this))
    {
        Console.WriteLine("start completed synchronously");
        completedCallback(this);
    }
}
catch (Ice.LocalException ex)
{
    _acceptorException = ex;
    completedCallback(this);
}

pepone commented 2 weeks ago

Handling the exception solves the shutdown hang. The acceptor is still closed as result of the exception and new connections are rejected.

bernardnormier commented 2 weeks ago

Good, can you create a PR to fix this bug?

pepone commented 2 weeks ago

I'm unable to reproduce the ArgumentException with a simpler test case in plain .NET.

bernardnormier commented 2 weeks ago

Sounds like https://github.com/dotnet/runtime/issues/102663 ?

pepone commented 2 weeks ago

Sounds like https://github.com/dotnet/runtime/issues/102663 ?

Yes. It is likely the same issue. I was able to reproduce the problem with a .NET debug build, and the test hits and assert in .NET. I reported the details in the dotnet/runtime issue issue with a possible workaround.

zeroc-ice / ice

Bug accepting timed-out connections with IPv6 (C#) #2677