Graceful shutdown regression

[halter73]

This issue is currently being obscured by aspnet/Logging#563, but here are the logs from Kestrel's sample app after Chrome opens two requests to http://localhost:5000. This is reproducible with and without connection adapters:

KestrelHttpServer\samples\SampleApp [dev ≡ +0 ~2 -0 !]> dotnet bin\Release\netcoreapp1.1\SampleApp.dll
Hosting environment: Production
Content root path: C:\Users\shalter\dev\misc\KestrelHttpServer\samples\SampleApp
Now listening on: http://127.0.0.1:5000
Now listening on: http://127.0.0.1:5001
Application started. Press Ctrl+C to shut down.
Connection id "0HL3IEM4MV4OC" started.
Connection id "0HL3IEM4MV4OC" completed keep alive response.
Connection id "0HL3IEM4MV4OC" completed keep alive response.
Connection id "0HL3IEM4MV4OD" started.
Application is shutting down...
Connection id "0HL3IEM4MV4OD" disconnecting.
Connection id "0HL3IEM4MV4OC" disconnecting.
Some connections failed to close gracefully during server shutdown.
Some connections failed to close gracefully during server shutdown.
Some connections failed to abort during server shutdown.
Some connections failed to abort during server shutdown.
Disposing write requests failed
Disposing write requests failed
KestrelThread.StopAsync failed to terminate libuv thread.
KestrelThread.StopAsync failed to terminate libuv thread.

If I had to guess, I would say this was likely regressed by #1497, but the parent commit no longer builds due to corefx(lab) changes.

You can see the logs during dispose using my halter73/1547 branch.

[davidfowl]

@halter73 are you going to fix this as part of your changes or do you want me to look at it?

[halter73]

I don't have the fix. I'm currently tying to stay focused on not regressing the current behavior.

I think this could fixed after my changes are merged, but by all means feel free to look at it.

[davidfowl]

I'll take a look.

[davidfowl]

Logging is the reason things are busted. Here's what happening:

• The browser connects
• User ends the application with Ctrl+C
• We start the shutdown sequence by looping over all connections and calling StopAsync()

  KestrelHttpServer/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Connection.cs

  Line 124 in 3e6303b

  return Task.WhenAll(_frame.StopAsync(), _socketClosedTcs.Task);

• That cancelling the frame's reading loop by calling CancelPendingRead().
• Frame unwinds successfully and in the finally block tries to end the connection via IConnectionControl.End(ProduceEndType.SocketShutdown) but this explodes because of logging is disposed (in particular, the console logger)
  

  KestrelHttpServer/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

  Line 215 in 3e6303b

  ConnectionControl.End(ProduceEndType.SocketShutdown);

• The catch block within the finally block in FrameOfT runs

  KestrelHttpServer/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

  Line 220 in 3e6303b

  Log.LogWarning(0, ex, "Connection shutdown abnormally");

• The frame task is marked as completed successfully but the _socketClosedTcs is never completed.

  KestrelHttpServer/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Connection.cs

  Line 124 in 3e6303b

  return Task.WhenAll(_frame.StopAsync(), _socketClosedTcs.Task);

[halter73]

Logging is definitely messing things up, but why does the halter73/1547 branch still fail when it's using a "fake" logger?

[davidfowl]

I didn't try your branch. Will take a look.

[davidfowl]

Tried your branch, seems like an issue with pipes. It seems like neither CancelPendingRead() no writer.Complete isn't yielding the read async in SocketOutput (which is strange). Hmm, these are being scheduled, let me check something.

[davidfowl]

@halter73 guess what the problem is 😄 . Like all problems of this class, something is blocking the libuv thread thus the socket output callback never gets scheduled. In particular

KestrelHttpServer/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/ConnectionManager.cs

Line 67 in 3e6303b

_threadPool.Run(() =>

, since we're using the configured thread pool here we don't get the desired affect which is the get off the libuv thread.

It's been a regression since we added the ability to change thread pool dispatching. It happens in the sample because it turns it off.

EDIT: Confirms it happens in feature/dev-si too (for the same reason)

[davidfowl]

The right fix is to avoid using the IThreadPool in the ConnectionManager and directly use Task.Run or TP.QUWI

[halter73]

Lol. I forgot that we had disabled thread pool dispatching in this sample. I already changed ConnectionManager to use Task.Run() for other reasons in my branch. Same for KestrelThread.DoPostWork().

[davidfowl]

😄 I'll close this bug