Unexpected exception in TimingPipeFlusher.FlushAsync in Kestrel

[cdlliuy]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

Team. we started to see Unexpected exception in TimingPipeFlusher.FlushAsync error blow from existing c# application recently with the latest aspnet linux docker image.

Given we didn't have changes in our side, wondering whether there are any hint for aspnet network changes to cause this? any information that we need to collect to expose this further?

Unexpected exception in TimingPipeFlusher.FlushAsync.
Exception: System.IO.IOException: The encryption operation failed, see inner exception.
 ---> Interop+OpenSsl+SslException: Encrypt failed with OpenSSL error - SSL_ERROR_SYSCALL.
 ---> System.IO.EndOfStreamException: Attempted to read past the end of the stream.
   --- End of inner exception stack trace ---
   at Interop.OpenSsl.Encrypt(SafeSslHandle context, ReadOnlySpan`1 input, Byte[]& output, SslErrorCode& errorCode)
   at System.Net.Security.SslStreamPal.EncryptMessage(SafeDeleteSslContext securityContext, ReadOnlyMemory`1 input, Int32 _, Int32 _1, Byte[]& output, Int32& resultSize)
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at System.IO.Pipelines.StreamPipeWriter.FlushAsyncInternal(Boolean writeToStream, ReadOnlyMemory`1 data, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at System.IO.Pipelines.StreamPipeWriter.FlushAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.PipeWriterHelpers.TimingPipeFlusher.FlushAsync(MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteGoAwayAsync(Int32 lastStreamId, Http2ErrorCode errorCode)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Threading.Tasks.Task.FinishSlow(Boolean userDelegateExecute)
   at System.Threading.Tasks.Task.TrySetException(Object exceptionObject)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetException(Exception exception, Task`1& taskField)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.TryReadPrefaceAsync()
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecuteFromThreadPool(Thread threadPoolThread)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
--- End of stack trace from previous location ---
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.IO.Pipelines.StreamPipeWriter.FlushAsyncInternal(Boolean writeToStream, ReadOnlyMemory`1 data, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.PipeWriterHelpers.ConcurrentPipeWriter.FlushAsyncAwaited(ValueTask`1 flushTask, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.PipeWriterHelpers.TimingPipeFlusher.TimeFlushAsyncAwaited(ValueTask`1 pipeFlushTask, MinDataRate minRate, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)o 

Expected Behavior

No response

Steps To Reproduce

No response

Exceptions (if any)

No response

.NET Version

No response

Anything else?

No response

[dotnet-policy-service]

Tagging subscribers to this area: @dotnet/ncl, @bartonjs, @vcsjones
See info in area-owners.md if you want to be subscribed.

[rzikm]

I don't think anything substantial changed in the area in the area in the last release, do you have a reproducible repro? This is somewhat difficult to debug without one.

[dotnet-policy-service]

This issue has been marked needs-author-action and may be missing some important information.

[wfurt]

What OS and OpenSSL version is in use? It is curious that OpenSSL tries to read and hits EOF. All that should be handled by .NET AFAIK....

[MarkMpn]

I think I am having the same issue. My stack trace is slightly different around some of the async frames but the key parts seem the same:

Unexpected exception in TimingPipeFlusher.FlushAsync.
System.IO.IOException: The encryption operation failed, see inner exception.
 ---> Interop+OpenSsl+SslException: Encrypt failed with OpenSSL error - SSL_ERROR_SYSCALL.
 ---> System.IO.EndOfStreamException: Attempted to read past the end of the stream.
   --- End of inner exception stack trace ---
   at Interop.OpenSsl.Encrypt(SafeSslHandle context, ReadOnlySpan`1 input, Byte[]& output, SslErrorCode& errorCode)
   at System.Net.Security.SslStreamPal.EncryptMessage(SafeDeleteSslContext securityContext, ReadOnlyMemory`1 input, Int32 _, Int32 _1, Byte[]& output, Int32& resultSize)
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at System.IO.Pipelines.StreamPipeWriter.FlushAsyncInternal(Boolean writeToStream, ReadOnlyMemory`1 data, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at System.IO.Pipelines.StreamPipeWriter.FlushAsync(CancellationToken cancellationToken)    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.PipeWriterHelpers.ConcurrentPipeWriter.FlushAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteGoAwayAsync(Int32 lastStreamId, Http2ErrorCode errorCode)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
--- End of stack trace from previous location ---
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.IO.Pipelines.StreamPipeWriter.FlushAsyncInternal(Boolean writeToStream, ReadOnlyMemory`1 data, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.PipeWriterHelpers.ConcurrentPipeWriter.FlushAsyncAwaited(ValueTask`1 flushTask, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.PipeWriterHelpers.TimingPipeFlusher.TimeFlushAsyncAwaited(ValueTask`1 pipeFlushTask, MinDataRate minRate, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)

My environment is:

$ dotnet --list-runtimes
Microsoft.AspNetCore.App 8.0.20 [/usr/lib/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.NETCore.App 8.0.20 [/usr/lib/dotnet/shared/Microsoft.NETCore.App]

$ openssl version
OpenSSL 3.0.13 30 Jan 2024 (Library: OpenSSL 3.0.13 30 Jan 2024)

$ uname -r
6.14.0-1012-azure

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 24.04.3 LTS
Release:        24.04
Codename:       noble

I'm afraid I don't have a simple repro at the moment, this is happening on a very small percentage of requests.

[rzikm]

Btw. the EndOfStreamException comes from here

runtime/src/libraries/Common/src/Interop/Unix/System.Security.Cryptography.Native/Interop.OpenSsl.cs

Lines 1018 to 1031 in 3d2e38a

	private static Exception? GetSslError(int result, Ssl.SslErrorCode retVal)
	{
	Exception? innerError;
	switch (retVal)
	{
	case Ssl.SslErrorCode.SSL_ERROR_SYSCALL:
	ErrorInfo lastErrno = Sys.GetLastErrorInfo();
	// Some I/O error occurred
	innerError =
	Crypto.ErrPeekError() != 0 ? Crypto.CreateOpenSslCryptographicException() : // crypto error queue not empty
	result == 0 ? new EndOfStreamException() : // end of file that violates protocol
	result == -1 && lastErrno.Error != Error.SUCCESS ? new IOException(lastErrno.GetErrorMessage(), lastErrno.RawErrno) : // underlying I/O error
	null; // no additional info available
	break;

Looking at the available documentation for SSL_ERROR_SYSCALL I am not sure if the order of checking retval and errno is correct, maybe the errno would give us more information in this case.

Given that the error happens during SSL_write, EOF does not really make sense. Until we have at least semi-reliable repro, this will be difficult to investiagte.

[MarkMpn]

Is there any extra information I could gather which might help diagnose further? I'm not in control of the clients connecting to this service, but if there's any more info I can gather server-side I'd be happy to help.

[rzikm]

Collecting private logs might help, see e.g. https://devblogs.microsoft.com/dotnet/net-5-new-networking-improvements/#consuming-telemetry-events how to setup collection.

Interesting data would be under these event sources
System.Net.Security
Private.InternalDiagnostics.System.Net.Security

Note that the logs are verbose and may log unredacted plaintext data (and thus potentially expose PII) When investigating those logs, I would look for the error message you are seeing and then look at all events logged for that particular stream instance (might not be straightforward, as some logs are linked against child objects of SslStream).

[MarkMpn]

I've run this with:

dotnet-trace collect --providers System.Net.Security,Private.InternalDiagnostics.System.Net.Security -o networking.nettrace -p <pid>

When I open the file in PerfView I can see events for:

• System.Net.Security/Handshake/Start
• System.Net.Security/Handshake/Stop
• System.Net.Security/HandshakeFailed

but nothing that seems obviously related to Private.InternalDiagnostics.System.Net.Security

The only error messages associated with any of these are in the System.Net.Security/HandshakeFailed events. The event that's closest in time to the last instance of this error we can see in our logs has the message "Received an unexpected EOF or 0 bytes from the transport stream." However, there are many other examples of this same message that don't correlate to the original exception, so I'm not sure this is relevant. Searching for "SSL_ERROR_SYSCALL" in the text filter produces no results.

It's quite possible I've missed something with how I'm collecting or looking at these logs, please let me know if there's a way for me to get more helpful information!