search

icerpc / icerpc-csharp

A C# RPC framework built for QUIC, with bidirectional streaming, first-class async/await, and Protobuf support.
https://docs.icerpc.dev
Apache License 2.0
107 stars 13 forks source link

Stack trace does not reliably show idle timer "abort" #3667

Closed bernardnormier closed 1 year ago

bernardnormier commented 1 year ago

When the idle timer aborts a transport connection (see #3665), the stack trace for the Shutdown failure (when log level = Debug) should show the issue, but does not do so reliably.

Good stack trace:

dbug: IceRpc.ClientConnection[3]
      Client connection from '[::1]:51276' to '[::1]:10000' connected
info: IceRpc.Logger.LoggerInterceptor[0]
      Sent request report to icerpc:/Igloo.ThermoHome over [::1]:51276<->[::1]:10000 and received a response with status code Ok
dbug: IceRpc.ClientConnection[10]
      Invocation 'report' on '/Igloo.ThermoHome' failed to send payload continuation to '[::1]:10000'
      IceRpc.IceRpcException: The connection was lost.
         at IceRpc.Transports.Slic.Internal.SlicConnection.ThrowIfClosed() in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 653
         at IceRpc.Transports.Slic.Internal.SlicStream.ThrowIfConnectionClosed() in /_/src/IceRpc/Transports/Slic/Internal/SlicStream.cs:line 401
         at IceRpc.Transports.Slic.Internal.SlicPipeWriter.WriteAsync(ReadOnlySequence`1 source, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicPipeWriter.cs:line 101
         at IceRpc.Internal.PipeWriterExtensions.WriteAsync(PipeWriter writer, ReadOnlySequence`1 source, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Internal/PipeWriterExtensions.cs:line 127
         at IceRpc.Internal.PipeWriterExtensions.<>c__DisplayClass2_0.<<CopyFromAsync>g__WriteReadResultAsync|0>d.MoveNext() in /_/src/IceRpc/Internal/PipeWriterExtensions.cs:line 100
      --- End of stack trace from previous location ---
         at IceRpc.Internal.PipeWriterExtensions.CopyFromAsync(PipeWriter writer, PipeReader reader, Task writesClosed, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Internal/PipeWriterExtensions.cs:line 80
         at IceRpc.Internal.IceRpcProtocolConnection.<>c__DisplayClass56_0.<<SendRequestPayloadContinuation>g__PerformSendRequestPayloadContinuationAsync|0>d.MoveNext() in /_/src/IceRpc/Internal/IceRpcProtocolConnection.cs:line 1535
dbug: IceRpc.ClientConnection[7]
      Client connection from '[::1]:51276' to '[::1]:10000' failed to shutdown
      IceRpc.IceRpcException: The connection did not receive any bytes for over 30 s.
         at IceRpc.Transports.Internal.IdleTimeoutDuplexConnectionDecorator.<>c__DisplayClass7_0.<<ReadAsync>g__PerformReadAsync|0>d.MoveNext() in /_/src/IceRpc/Transports/Internal/IdleTimeoutDuplexConnectionDecorator.cs:line 51
      --- End of stack trace from previous location ---
         at IceRpc.Transports.Internal.DuplexConnectionReader.ReadAsyncCore(Int32 minimumSize, Boolean canReturnEmptyBuffer, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Internal/DuplexConnectionReader.cs:line 171
         at IceRpc.Transports.Slic.Internal.SlicConnection.ReadFrameHeaderAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 1252
         at IceRpc.Transports.Slic.Internal.SlicConnection.ReadFramesAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 1333
         at IceRpc.Internal.ExceptionUtil.Throw(Exception exception) in /_/src/IceRpc/Internal/ExceptionUtil.cs:line 14
         at IceRpc.Transports.Slic.Internal.SlicConnection.AcceptStreamAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 118
         at IceRpc.Internal.IceRpcProtocolConnection.AcceptRequestsAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Internal/IceRpcProtocolConnection.cs:line 901
         at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
         at System.IO.Pipelines.Pipe.GetReadAsyncResult()
         at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
         at IceRpc.Transports.Slic.Internal.SlicPipeReader.ReadAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicPipeReader.cs:line 77
         at IceRpc.Internal.IceRpcProtocolConnection.ReceiveControlFrameHeaderAsync(IceRpcControlFrameType expectedFrameType, CancellationToken cancellationToken) in /_/src/IceRpc/Internal/IceRpcProtocolConnection.cs:line 1383
         at IceRpc.Internal.IceRpcProtocolConnection.ReadGoAwayAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Internal/IceRpcProtocolConnection.cs:line 1328
         at IceRpc.Internal.IceRpcProtocolConnection.<>c__DisplayClass39_0.<<ShutdownAsync>g__PerformShutdownAsync|0>d.MoveNext() in /_/src/IceRpc/Internal/IceRpcProtocolConnection.cs:line 653
      --- End of stack trace from previous location ---
         at IceRpc.Internal.MetricsProtocolConnectionDecorator.ShutdownAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Internal/MetricsProtocolConnectionDecorator.cs:line 61
         at IceRpc.Internal.LogProtocolConnectionDecorator.ShutdownAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Internal/LogProtocolConnectionDecorator.cs:line 77

Bad stack trace (same code):

dbug: IceRpc.ClientConnection[3]
      Client connection from '[::1]:51186' to '[::1]:10000' connected
info: IceRpc.Logger.LoggerInterceptor[0]
      Sent request report to icerpc:/Igloo.ThermoHome over [::1]:51186<->[::1]:10000 and received a response with status code Ok
dbug: IceRpc.ClientConnection[7]
      Client connection from '[::1]:51186' to '[::1]:10000' failed to shutdown
      System.OperationCanceledException: The operation was canceled.
         at System.Threading.CancellationToken.ThrowOperationCanceledException()
         at System.Threading.CancellationToken.ThrowIfCancellationRequested()
         at IceRpc.Internal.IceRpcProtocolConnection.<>c__DisplayClass39_0.<<ShutdownAsync>g__PerformShutdownAsync|0>d.MoveNext() in /_/src/IceRpc/Internal/IceRpcProtocolConnection.cs:line 724
      --- End of stack trace from previous location ---
         at IceRpc.Internal.MetricsProtocolConnectionDecorator.ShutdownAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Internal/MetricsProtocolConnectionDecorator.cs:line 61
         at IceRpc.Internal.LogProtocolConnectionDecorator.ShutdownAsync(CancellationToken cancellationToken) in /_/src/IceRpc/Internal/LogProtocolConnectionDecorator.cs:line 77
dbug: IceRpc.ClientConnection[10]
      Invocation 'report' on '/Igloo.ThermoHome' failed to send payload continuation to '[::1]:10000'
      IceRpc.IceRpcException: The connection was lost.
         at IceRpc.Transports.Slic.Internal.SlicConnection.ThrowIfClosed() in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 653
         at IceRpc.Transports.Slic.Internal.SlicStream.ThrowIfConnectionClosed() in /_/src/IceRpc/Transports/Slic/Internal/SlicStream.cs:line 401
         at IceRpc.Transports.Slic.Internal.SlicPipeWriter.WriteAsync(ReadOnlySequence`1 source, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicPipeWriter.cs:line 101
         at IceRpc.Internal.PipeWriterExtensions.WriteAsync(PipeWriter writer, ReadOnlySequence`1 source, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Internal/PipeWriterExtensions.cs:line 127
         at IceRpc.Internal.PipeWriterExtensions.<>c__DisplayClass2_0.<<CopyFromAsync>g__WriteReadResultAsync|0>d.MoveNext() in /_/src/IceRpc/Internal/PipeWriterExtensions.cs:line 100
      --- End of stack trace from previous location ---
         at IceRpc.Internal.PipeWriterExtensions.CopyFromAsync(PipeWriter writer, PipeReader reader, Task writesClosed, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Internal/PipeWriterExtensions.cs:line 80
         at IceRpc.Internal.IceRpcProtocolConnection.<>c__DisplayClass56_0.<<SendRequestPayloadContinuation>g__PerformSendRequestPayloadContinuationAsync|0>d.MoveNext() in /_/src/IceRpc/Internal/IceRpcProtocolConnection.cs:line 1535
dbug: IceRpc.ClientConnection[5]
      Client connection from '[::1]:51186' to '[::1]:10000' disposed

In the bad case, it seems the shutdown hangs and times out instead of reporting immediately the Slic connection failure.

bernardnormier commented 1 year ago

It was a "user error". I forgot to call ShutdownAsync on my ClientConnection. As a result, ClientConnection's DisposeAsync was canceling outstanding connection shutdown.

Lesson: if you see

  Client connection from '[::1]:51186' to '[::1]:10000' failed to shutdown
      System.OperationCanceledException: The operation was canceled.
         at System.Threading.CancellationToken.ThrowOperationCanceledException()
         at System.Threading.CancellationToken.ThrowIfCancellationRequested()
         at IceRpc.Internal.IceRpcProtocolConnection.<>c__DisplayClass39_0.<<ShutdownAsync>g__PerformShutdownAsync|0>d.MoveNext() in /_/src/IceRpc/Internal/IceRpcProtocolConnection.cs:line 724

Make sure you didn't forget to call ShutdownAsync on your ClientConnection or ConnectionCache.