Ssl_server_connection_connect_fails_when_client_provides_untrusted_certificate failure

[bernardnormier]

Got this failure in PR build, which seems totally unrelated to my PR:

  Failed IceRpc:Tests:Transports:Slic:SlicTransportSslAuthenticationConformanceTests:Ssl_server_connection_connect_fails_when_client_provides_untrusted_certificate [7 s]
  Stack Trace:
  Passed IceRpc:Tests:Transports:Tcp:TcpListenerConformanceTests:Connect_fails_if_listener_is_disposed [1 s]

See https://github.com/icerpc/icerpc-csharp/actions/runs/6398340097/job/17368272715?pr=3670

[pepone]

I cannot reproduce with main, I see that in the linked log there is also another failure:

Failed IceRpc:Tests:Transports:Tcp:SslConnectionConformanceTests:Read_on_peer_returns_zero_after_shutdown_write [8 s]

[pepone]

The missing stack trace is addressed in nunit/milestone/42. The fix is done but hasn't been released yet.

[pepone]

One possible explanation for this failure is

// Start the TLS handshake by calling connect on the client and server connections and wait for the
// connection establishment.
var clientConnectTask = sut.Client.ConnectAsync(default);

// Act/Assert
IMultiplexedConnection? serverConnection = null;
Assert.That(
    async () =>
    {
        // We accept two behaviors here:
        // - the listener can internally kill the client connection if it's not valid (e.g.: Quic behavior)
        // - the listener can return the connection but ConnectAsync fails (e.g.: Slic behavior)
        using var cts = new CancellationTokenSource(TimeSpan.FromMilliseconds(250));
        (serverConnection, _) = await listener.AcceptAsync(cts.Token);
        await serverConnection.ConnectAsync(default);
    },
    Throws.TypeOf<AuthenticationException>().Or.InstanceOf<OperationCanceledException>());

For Slic, we expect:

• Server accepts the connection.
• ConnectAsync fails with AuthenticationException.

For QUIC, we expect:

• The listener terminates the connection and throws OperationCanceledException.

In the second assert, we have:

Assert.That(
    async () =>
    {
        // We accept two behaviors here:
        // - the client connection fails with AuthenticationException when try to create a stream
        //   (e.g.: Quic behavior)
        // - the client connect operation fails with either TransportException (e.g: Slic behavior).
        if (serverConnection is not null)
        {
            await serverConnection.DisposeAsync();
        }
        await clientConnectTask;
        var stream = await sut.Client.CreateStreamAsync(bidirectional: false, CancellationToken.None);
        await stream.Output.WriteAsync(new ReadOnlyMemory<byte>(new byte[] { 0xFF }), CancellationToken.None);
    },
    Throws.TypeOf<AuthenticationException>().Or.TypeOf<IceRpcException>());

The disposal of serverConnection was added to fix #2074.

In this test, if the Slic listener throws an OperationCanceledException because the VM is running slow, the connection will not start the SSL handshake, and as a result, the connect task will hang waiting for the connect timeout to kick in.

The QUIC and Slic behaviors here are quite different, making this test brittle, I propose we split this test into separate tests for Slic and QUIC and leave it out of the transport conformance tests.

[bernardnormier]

I agree, we should convert this test in Slic and QUIC -specific tests

[pepone]

I simplified the test, There was a hang again with Slic, but this time there was also an unobserved task exception

2023-10-06T20:20:21.4846702Z +++ Unobserved task exception System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[IceRpc.Transports.TransportConnectionInformation,IceRpc.Transports.Slic.Internal.SlicConnection+<>c__DisplayClass56_0+<<ConnectAsync>g__PerformConnectAsync|0>d]:
2023-10-06T20:20:21.4848317Z IceRpc.IceRpcException: An IceRpc call failed with error 'ConnectionAborted'.
2023-10-06T20:20:21.4849367Z  ---> System.IO.IOException: Unable to read data from the transport connection: Connection reset by peer.
2023-10-06T20:20:21.4850431Z  ---> System.Net.Sockets.SocketException (104): Connection reset by peer
2023-10-06T20:20:21.4851641Z    at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.CreateException(SocketError error, Boolean forAsyncThrow)
2023-10-06T20:20:21.4852556Z    at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ReceiveAsync(Socket socket, CancellationToken cancellationToken)
2023-10-06T20:20:21.4853834Z    at System.Net.Sockets.Socket.ReceiveAsync(Memory`1 buffer, SocketFlags socketFlags, Boolean fromNetworkStream, CancellationToken cancellationToken)
2023-10-06T20:20:21.4854637Z    at System.Net.Sockets.NetworkStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
2023-10-06T20:20:21.4856098Z    at System.Net.Security.SslStream.EnsureFullTlsFrameAsync[TIOAdapter](CancellationToken cancellationToken)
2023-10-06T20:20:21.4857301Z    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
2023-10-06T20:20:21.4858172Z    at System.Net.Security.SslStream.EnsureFullTlsFrameAsync[TIOAdapter](CancellationToken cancellationToken)
2023-10-06T20:20:21.4858831Z    at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](Memory`1 buffer, CancellationToken cancellationToken)
2023-10-06T20:20:21.4859490Z    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
2023-10-06T20:20:21.4860152Z    at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](Memory`1 buffer, CancellationToken cancellationToken)
2023-10-06T20:20:21.4860870Z    at IceRpc.Transports.Tcp.Internal.TcpConnection.<>c__DisplayClass12_0.<<ReadAsync>g__PerformReadAsync|0>d.MoveNext() in /_/src/IceRpc/Transports/Tcp/Internal/TcpConnection.cs:line 72
2023-10-06T20:20:21.4861592Z    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
2023-10-06T20:20:21.4862240Z    at IceRpc.Transports.Tcp.Internal.TcpConnection.<>c__DisplayClass12_0.<ReadAsync>g__PerformReadAsync|0()
2023-10-06T20:20:21.4863138Z    at IceRpc.Transports.Tcp.Internal.TcpConnection.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Tcp/Internal/TcpConnection.cs:line 65
2023-10-06T20:20:21.4864114Z    at IceRpc.Transports.Slic.Internal.SlicDuplexConnectionDecorator.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicDuplexConnectionDecorator.cs:line 35
2023-10-06T20:20:21.4865601Z    at IceRpc.Transports.Internal.DuplexConnectionReader.ReadAsyncCore(Int32 minimumSize, Boolean canReturnEmptyBuffer, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Internal/DuplexConnectionReader.cs:line 171
2023-10-06T20:20:21.4866991Z    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
2023-10-06T20:20:21.4868284Z    at IceRpc.Transports.Internal.DuplexConnectionReader.ReadAsyncCore(Int32 minimumSize, Boolean canReturnEmptyBuffer, CancellationToken cancellationToken)
2023-10-06T20:20:21.4869146Z    at IceRpc.Transports.Internal.DuplexConnectionReader.ReadAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Internal/DuplexConnectionReader.cs:line 121
2023-10-06T20:20:21.4870037Z    at IceRpc.Transports.Slic.Internal.SlicConnection.ReadFrameHeaderAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 1261
2023-10-06T20:20:21.4870816Z    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
2023-10-06T20:20:21.4871505Z    at IceRpc.Transports.Slic.Internal.SlicConnection.ReadFrameHeaderAsync(CancellationToken cancellationToken)
2023-10-06T20:20:21.4872264Z    at IceRpc.Transports.Slic.Internal.SlicConnection.<>c__DisplayClass56_0.<<ConnectAsync>g__ReadFrameAsync|3>d`1.MoveNext() in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 321
2023-10-06T20:20:21.4873177Z    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
2023-10-06T20:20:21.4873911Z    at IceRpc.Transports.Slic.Internal.SlicConnection.<>c__DisplayClass56_0.<ConnectAsync>g__ReadFrameAsync|3[T](Func`3 decodeFunc, CancellationToken cancellationToken)
2023-10-06T20:20:21.4874724Z    at IceRpc.Transports.Slic.Internal.SlicConnection.<>c__DisplayClass56_0.<<ConnectAsync>g__PerformConnectAsync|0>d.MoveNext() in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 156
2023-10-06T20:20:21.4876652Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2023-10-06T20:20:21.4877437Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
2023-10-06T20:20:21.4878221Z    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
2023-10-06T20:20:21.4879119Z    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
2023-10-06T20:20:21.4880109Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
2023-10-06T20:20:21.4880914Z    at IceRpc.Transports.Tcp.Internal.TcpServerConnection.ConnectAsyncCore(CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Tcp/Internal/TcpConnection.cs:line 410
2023-10-06T20:20:21.4881714Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2023-10-06T20:20:21.4882405Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
2023-10-06T20:20:21.4883124Z    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
2023-10-06T20:20:21.4883757Z    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
2023-10-06T20:20:21.4884235Z    at System.Threading.Tasks.Task`1.TrySetResult(TResult result)
2023-10-06T20:20:21.4884788Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
2023-10-06T20:20:21.4885420Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult()
2023-10-06T20:20:21.4886143Z    at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)
2023-10-06T20:20:21.4886904Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
2023-10-06T20:20:21.4892309Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2023-10-06T20:20:21.4893214Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
2023-10-06T20:20:21.4894161Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
2023-10-06T20:20:21.4896150Z    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
2023-10-06T20:20:21.4896879Z    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
2023-10-06T20:20:21.4897529Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
2023-10-06T20:20:21.4898218Z    at System.Net.Security.SslStream.ReceiveBlobAsync[TIOAdapter](CancellationToken cancellationToken)
2023-10-06T20:20:21.4898931Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
2023-10-06T20:20:21.4900110Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2023-10-06T20:20:21.4900812Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
2023-10-06T20:20:21.4904970Z    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
2023-10-06T20:20:21.4905686Z    at System.Net.Security.SslStream.EnsureFullTlsFrameAsync[TIOAdapter](CancellationToken cancellationToken)
2023-10-06T20:20:21.4906423Z    at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.ExecutionContextCallback(Object s)
2023-10-06T20:20:21.4907160Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2023-10-06T20:20:21.4907853Z    at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.MoveNext()
2023-10-06T20:20:21.4908688Z    at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.InvokeContinuation(Action`1 continuation, Object state, Boolean forceAsync, Boolean requiresExecutionContextFlow)
2023-10-06T20:20:21.4909766Z    at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.OnCompleted(SocketAsyncEventArgs _)
2023-10-06T20:20:21.4910519Z    at System.Net.Sockets.SocketAsyncEngine.System.Threading.IThreadPoolWorkItem.Execute()
2023-10-06T20:20:21.4911267Z    at System.Threading.ThreadPoolWorkQueue.Dispatch()
2023-10-06T20:20:21.4911788Z    at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
2023-10-06T20:20:21.4912414Z --- End of stack trace from previous location ---
2023-10-06T20:20:21.4912623Z 
2023-10-06T20:20:21.4913017Z    --- End of inner exception stack trace ---
2023-10-06T20:20:21.4913531Z    at System.Net.Security.SslStream.EnsureFullTlsFrameAsync[TIOAdapter](CancellationToken cancellationToken)
2023-10-06T20:20:21.4914353Z    at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
2023-10-06T20:20:21.4915488Z    at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](Memory`1 buffer, CancellationToken cancellationToken)
2023-10-06T20:20:21.4916302Z    at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
2023-10-06T20:20:21.4917165Z    at IceRpc.Transports.Tcp.Internal.TcpConnection.<>c__DisplayClass12_0.<<ReadAsync>g__PerformReadAsync|0>d.MoveNext() in /_/src/IceRpc/Transports/Tcp/Internal/TcpConnection.cs:line 72
2023-10-06T20:20:21.4917782Z    --- End of inner exception stack trace ---
2023-10-06T20:20:21.4918341Z    at IceRpc.Transports.Tcp.Internal.TcpConnection.<>c__DisplayClass12_0.<<ReadAsync>g__PerformReadAsync|0>d.MoveNext() in /_/src/IceRpc/Transports/Tcp/Internal/TcpConnection.cs:line 78
2023-10-06T20:20:21.4919309Z --- End of stack trace from previous location ---
2023-10-06T20:20:21.4920274Z    at IceRpc.Transports.Internal.DuplexConnectionReader.ReadAsyncCore(Int32 minimumSize, Boolean canReturnEmptyBuffer, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Internal/DuplexConnectionReader.cs:line 171
2023-10-06T20:20:21.4921595Z    at IceRpc.Transports.Slic.Internal.SlicConnection.ReadFrameHeaderAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 1261
2023-10-06T20:20:21.4922814Z    at IceRpc.Transports.Slic.Internal.SlicConnection.<>c__DisplayClass56_0.<<ConnectAsync>g__ReadFrameAsync|3>d`1.MoveNext() in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 321
2023-10-06T20:20:21.4923803Z --- End of stack trace from previous location ---

[pepone]

This just failed again on main with the Split test

2023-10-10T15:03:34.4516244Z   Failed IceRpc:Tests:Transports:Slic:SlicTransportSslAuthenticationTests:Slic_over_ssl_server_connection_connect_fails_when_client_provides_untrusted_certificate [8 s]
2023-10-10T15:03:34.4516983Z   Stack Trace:

https://github.com/icerpc/icerpc-csharp/actions/runs/6471106559/job/17568817075

[pepone]

Fixed in 843b6b8, that was failing when using many test workers on Slow VMs