`System.IO.IOException` throws 2 times when Unity Editor stops playing
Closed this issue · 5 comments
Hello!
First of all, thank you very much for building this repository. It serves a really good reference for how to bridge the gap between gRPC and Unity via BestHTTP2 layer.
However, I'm seeing a weird behavior in the Unity Editor which is that .NET backend throws 2 System.IO.IOExceptions right after I stop playing.
Here, I'm pasting the call-stacks first, then I'll try to explain repro steps better:
fail: Microsoft.AspNetCore.Server.Kestrel[0]
Unexpected exception in TimingPipeFlusher.FlushAsync.
System.IO.IOException: The encryption operation failed, see inner exception.
---> System.ComponentModel.Win32Exception (14): Bad address
--- 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.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.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.IO.Pipelines.StreamPipeWriter.FlushAsyncInternal(Boolean writeToStream, ReadOnlyMemory`1 data, CancellationToken cancellationToken)
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.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.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()
at System.Threading.Thread.StartCallback()
--- 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)
fail: Microsoft.AspNetCore.Server.Kestrel[0]
Unhandled exception while processing 0HMROUKQB1N6K.
System.IO.IOException: The encryption operation failed, see inner exception.
---> System.ComponentModel.Win32Exception (14): Bad address
--- 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.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.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.IO.Pipelines.StreamPipeWriter.FlushAsyncInternal(Boolean writeToStream, ReadOnlyMemory`1 data, CancellationToken cancellationToken)
at System.IO.Pipelines.StreamPipeWriter.CompleteAsync(Exception exception)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.IO.Pipelines.StreamPipeWriter.CompleteAsync(Exception exception)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.DuplexPipeStreamAdapter`1.DisposeAsync()
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.DuplexPipeStreamAdapter`1.DisposeAsync()
at Microsoft.AspNetCore.Server.Kestrel.Https.Internal.HttpsConnectionMiddleware.OnConnectionAsync(ConnectionContext context)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
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`1.TrySetResult(TResult result)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult()
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.HttpConnection.ProcessRequestsAsync[TContext](IHttpApplication`1 httpApplication)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
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`1.TrySetResult(TResult result)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult()
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
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`1.TrySetResult(TResult result)
at System.Threading.Tasks.UnwrapPromise`1.TrySetFromTask(Task task, Boolean lookForOce)
at System.Threading.Tasks.UnwrapPromise`1.InvokeCore(Task completingTask)
at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
at System.Threading.Tasks.Task`1.TrySetResult(TResult result)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult()
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteToOutputPipe()
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
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.ThreadPoolWorkQueue.Dispatch()
at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
at System.Threading.Thread.StartCallback()
--- 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 System.IO.Pipelines.StreamPipeWriter.CompleteAsync(Exception exception)
at System.IO.Pipelines.StreamPipeWriter.CompleteAsync(Exception exception)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.DuplexPipeStreamAdapter`1.DisposeAsync()
at Microsoft.AspNetCore.Server.Kestrel.Https.Internal.HttpsConnectionMiddleware.OnConnectionAsync(ConnectionContext context)
at Microsoft.AspNetCore.Server.Kestrel.Https.Internal.HttpsConnectionMiddleware.OnConnectionAsync(ConnectionContext context)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelConnection`1.ExecuteAsync()
I have a simple gRPC test code on the Unity side:
public class GrpcTest : MonoBehaviour
{
private async void Start()
{
var grpcChannel = GrpcChannel.ForAddress("https://localhost:8888", new() { HttpHandler = new GrpcClientHttp2Handler() });
var demoClient = new Demo.DemoClient(grpcChannel);
var helloResponse = await demoClient.HelloAsync(new()
{
Name = "Unity",
Timestamp = DateTimeOffset.UtcNow.ToUnixTimeSeconds()
});
// ...The GrpcClientHttp2Handler class is basically GRPCBestHttpHandler from your repo.
What happens is that when I enter playmode, everything works perfectly and I get no errors, no exceptions or whatsoever.
However, when I stop playmode, I immediately see the call-stack above with 2 exceptions thrown.
It does not happen always but it happens quite frequently (most of the time 50/50 chance).
I suspect that gRPC initiates another request or come TCP connection via HTTP2 upon shutdown/disposal, or some stream gets closed prematurely.
But the problem is, I did wait for a full minute after getting the response from the backend for my gRPC request and then stopped playing, exceptions were still thrown.
I wonder if you bumped into this issue and/or can guide me through debugging and potentially bug fixing this for us.
I hope you don't mind me bugging you with this on your experimental repo — thanks in advance! :)
But the problem is, I did wait for a full minute after getting the response from the backend for my gRPC request and then stopped playing, exceptions were still thrown.
gRPC uses HTTP/2 and HTTP/2 has its own connection management, that means, the underlying connection is kept open for future use. (You can set the plugin's logging level and you can see the plugin and the server still exchanging messages way after your request.)
In the Unity editor when you exit play mode the editor shuts down everything and the plugin just has no time to gracefully disconnect from the server by sending and receiving HTTP/2 frames. It has to close and free up resources as soon as it just can.
This means that the server might not know that the client went down and disconnected and the next time it tries to send its regular messages, it will fail doing so.
@Benedicht thanks for the hint, I was assuming that it was a premature connection/stream close but I couldn't put my finger on it.
I tried to add 3 more lines at the end of the Start() method trying to dispose/shutdown stuff but it looks like it doesn't help:
await grpcChannel.ShutdownAsync();
grpcChannel.Dispose();
grpcHttp2Handler.Dispose();What would be the idiomatic way of handling this? Should we somehow force BestHTTP2 to close connections (IDK how but let's say we can) before ApplicationQuit or inside an OnApplicationQuit() call? Should we just handle and ignore AspNetCore Kestrel's exceptions, treating it like it's totally OK and move on?
(Oh, I also realized you're the author of BestHTTP2 -if I'm not wrong-. If so, hey! It's a wonderful plugin and thank you for participating in the open-source community!)
await grpcChannel.ShutdownAsync();
grpcChannel.Dispose();
grpcHttp2Handler.Dispose();Neither of those will shut down the HTTP/2 connection. What i would suggest is to adjust how much time the HTTP/2 connection could remain idle after serving all requests (Its default value is 2 minutes - it's a client-side value, the server can gracefully close the connection sooner):
BestHTTP.HTTPManager.HTTP2Settings.MaxIdleTime = TimeSpan.FromSeconds(10);Exiting playmode before the HTTP/2 connection would reach this idle time will still might produce an error on the server just like in the opening post, but it should be much rarer.
But this way the connection still has a chance to serve additional requests without doing round trips to build up a new connection, and still have a chance to close it the graceful way.
Thanks for the tip but I think lowering idle timeout to avoid a premature TCP stream close wouldn't be ideal but instead, deterministically controlling when "GOAWAY" packet would be sent for the last time would be a bit better such that we could send it right around closing the app.
I managed to track the procedure down this code block and I'll try to craft an HTTPRequest and pass it over to HTTP2Handler.Process() method (which would be the "GOAWAY" packet we'd like to send) then run HTTP2Handler one more time to send it over the wire.
if (this.ShutdownType == ShutdownTypes.Running && now - this.lastInteraction >= HTTPManager.HTTP2Settings.MaxIdleTime)
{
this.lastInteraction = DateTime.UtcNow;
HTTPManager.Logger.Information("HTTP2Handler", "Reached idle time, sending GoAway frame!", this.Context);
this.outgoingFrames.Add(HTTP2FrameHelper.CreateGoAwayFrame(0, HTTP2ErrorCodes.NO_ERROR));
this.goAwaySentAt = DateTime.UtcNow;
}Nevertheless, it's good to know that it is indeed premature socket close causing that exception on the AspNetCore side — I think I'll implement an exception handler and simply ignore it at the end.
You could use the HTTPRequest's Tag property. You can assign anything you want to it, the plugin doesn't use it. So you can create a blank custom class, create and assign a new instance of it when you want to close the HTTP/2 connection.
In the HTTP/2 handler you have to check the Tag and send the go_away frame.
Something like this (around line 319 of HTTP2Handler.cs):
// grab requests from queue
HTTPRequest request;
while (this.clientInitiatedStreams.Count < maxConcurrentStreams && this.requestQueue.TryDequeue(out request))
{
if (request.Tag is CloseHTTP2Connection)
{
HTTPManager.Logger.Information("HTTP2Handler", $"Found request with {nameof(CloseHTTP2Connection)} instance!", this.Context);
this.lastInteraction = DateTime.UtcNow;
this.outgoingFrames.Add(HTTP2FrameHelper.CreateGoAwayFrame(0, HTTP2ErrorCodes.NO_ERROR));
this.goAwaySentAt = DateTime.UtcNow;
break;
}
// ...
}CloseHTTP2Connection is just an empty one:
public sealed class CloseHTTP2Connection { }And creating the request:
var request = new HTTPRequest(new Uri("https://server"));
request.Tag = new CloseHTTP2Connection();
request.Send();This should work, but i see a few issues with it. If the connection already closing, the plugin will create a new connection and will close it immediately (using client and server resources). If new requests are created and assigned to the handler, they will be further delayed.
It could be further improved to handle edge cases.
I still would suggest to only use a lowered MaxIdleTime. You can lower the chances of connection losses, but they will never be zero.