Aspnetcore: [CI Failure] EmitsConnectionStartAndStop

Created on 26 Dec 2018 · 9Comments · Source: dotnet/aspnetcore

https://dnceng.visualstudio.com/public/_build/results?buildId=63309

We need more logging to determine whats happening.

Starting test execution, please wait...
2018-12-26T05:23:06.8651889Z   [xUnit.net 00:00:14.23]     EmitsConnectionStartAndStop [FAIL]
2018-12-26T05:23:06.8657652Z   Failed   EmitsConnectionStartAndStop
2018-12-26T05:23:06.8660915Z   Error Message:
2018-12-26T05:23:06.8663498Z    The collection was expected to contain a single element, but it was empty.
2018-12-26T05:23:06.8678877Z   Stack Trace:
2018-12-26T05:23:06.8680079Z      at Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.EventSourceTests.EmitsConnectionStartAndStop() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/EventSourceTests.cs:line 64
2018-12-26T05:23:06.8688487Z   --- End of stack trace from previous location where exception was thrown ---
2018-12-26T05:23:06.8690531Z   Standard Output Messages:
2018-12-26T05:23:06.8691414Z    | [0.001s] TestLifetime Information: Starting test EmitsConnectionStartAndStop at 2018-12-26T05:22:53
2018-12-26T05:23:06.8691822Z    | [0.003s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting starting
2018-12-26T05:23:06.8692254Z    | [0.004s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting started
2018-12-26T05:23:06.8692580Z    | [0.004s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Loaded hosting startup assembly testhost
2018-12-26T05:23:06.8692958Z    | [0.004s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" started.
2018-12-26T05:23:06.8693451Z    | [0.520s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.1 GET http:///  
2018-12-26T05:23:06.8693839Z    | [0.520s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" completed keep alive response.
2018-12-26T05:23:06.8694341Z    | [0.533s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request finished in 12.9394ms 200 
2018-12-26T05:23:06.8694802Z    | [4.383s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting shutdown
2018-12-26T05:23:06.8695120Z    | [9.412s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to close gracefully during server shutdown.
2018-12-26T05:23:06.8695520Z    | [9.415s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" closing because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout."
2018-12-26T05:23:06.8696095Z    | [10.379s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" closing because: "The client closed the connection."
2018-12-26T05:23:06.8703112Z    | [10.379s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" disconnecting.
2018-12-26T05:23:06.8706229Z    | [10.429s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to abort during server shutdown.
2018-12-26T05:23:06.8711344Z    | [10.586s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" stopped.
2018-12-26T05:23:06.8714695Z    | [10.679s] TestLifetime Information: Finished test EmitsConnectionStartAndStop in 10.6787548s

area-servers servers-kestrel

Source

davidfowl

Most helpful comment

Fixed in https://github.com/aspnet/AspNetCore/commit/010c1f0c9f22fba3f6a0e82461fa7553e9114b44

davidfowl on 30 Dec 2018

🎉2 👍2

All 9 comments

GOOD RUN

| [0.014s] TestLifetime Information: Starting test EmitsConnectionStartAndStop at 2018-12-27T13:23:42
| [0.138s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting starting
| [0.203s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting started
| [0.203s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Loaded hosting startup assembly testhost
| [0.229s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJBVQ2TNR48" started.
| [0.386s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.1 GET http:///  
| [0.412s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJBVQ2TNR48" completed keep alive response.
| [0.414s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request finished in 30.0722ms 200 
| [0.424s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJBVQ2TNR48" disconnecting.
| [0.426s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJBVQ2TNR48" closing because: "The client closed the connection."
| [0.427s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJBVQ2TNR48" stopped.
| [0.427s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting shutdown
| [0.456s] TestLifetime Information: Finished test EmitsConnectionStartAndStop in 0.4500344s

BAD RUN

| [0.001s] TestLifetime Information: Starting test EmitsConnectionStartAndStop at 2018-12-26T05:22:53
| [0.003s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting starting
| [0.004s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting started
| [0.004s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Loaded hosting startup assembly testhost
| [0.004s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" started.
| [0.520s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.1 GET http:///  
| [0.520s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" completed keep alive response.
| [0.533s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request finished in 12.9394ms 200 
| [4.383s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting shutdown
| [9.412s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to close gracefully during server shutdown.
| [9.415s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" closing because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout."
| [10.379s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" closing because: "The client closed the connection."
| [10.379s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" disconnecting.
| [10.429s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to abort during server shutdown.
| [10.586s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJAU8N3AQEG" stopped.
| [10.679s] TestLifetime Information: Finished test EmitsConnectionStartAndStop in 10.6787548s

davidfowl on 27 Dec 2018

It might be an issue with the InMemoryTransport. Adding more logging to figure it out.

davidfowl on 27 Dec 2018

| [0.002s] TestLifetime Information: Starting test EmitsConnectionStartAndStop at 2018-12-27T14:25:23
| [0.004s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting starting
| [0.005s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting started
| [0.005s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Loaded hosting startup assembly testhost
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC0SHLM2I2" started.
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequestsAsync started
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequests started
| [0.893s] Microsoft.AspNetCore.Server.Kestrel Debug: Result IsCompleted=False, IsCancelled=False 
| [0.893s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.1 GET http:///  
| [0.894s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC0SHLM2I2" completed keep alive response.
| [0.894s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request finished in 0.6672ms 200 
| [1.603s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting shutdown
| [1.603s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.StopProcessingNextRequest(Selected)
| [1.603s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.StopProcessingNextRequest()
| [7.441s] Microsoft.AspNetCore.Server.Kestrel Debug: Transport.Input.OnWriterCompleted fired
| [7.441s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.OnInputOrOutputCompleted(Selected)
| [7.441s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC0SHLM2I2" closing because: "The client closed the connection."
| [7.441s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC0SHLM2I2" disconnecting.
| [7.441s] Microsoft.AspNetCore.Server.Kestrel Debug: Result IsCompleted=True, IsCancelled=True 
| [7.441s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequests ended because endConnection=true
| [7.441s] Microsoft.AspNetCore.Server.Kestrel Debug: Transport.Output.OnReaderCompleted fired
| [7.441s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.OnInputOrOutputCompleted(Selected)
| [8.997s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to close gracefully during server shutdown.
| [8.997s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC0SHLM2I2" closing because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout."
| [10.143s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to abort during server shutdown.
| [10.156s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequestsAsync ended
| [10.171s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC0SHLM2I2" stopped.
| [10.176s] TestLifetime Information: Finished test EmitsConnectionStartAndStop in 10.1743373s

davidfowl on 27 Dec 2018

More logging, and another bad run. It seems like there's a long delay between disposing the client connection and OnWriterCompleted firing. Maybe it has something to do with thread pool starvation? Or thread pool exhaustion?

| [0.009s] TestLifetime Information: Starting test EmitsConnectionStartAndStop at 2018-12-27T20:42:03
| [0.093s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting starting
| [0.127s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting started
| [0.127s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Loaded hosting startup assembly testhost
| [0.146s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC7F149DOI" started.
| [0.164s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequestsAsync started
| [0.177s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequests started
| [0.178s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRequestProcessing
| [0.185s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRead
| [0.961s] Microsoft.AspNetCore.Server.Kestrel Debug: Result IsCompleted=False, IsCancelled=False 
| [0.962s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.1 GET http:///  
| [0.962s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC7F149DOI" completed keep alive response.
| [0.962s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request finished in 0.6331ms 200 
| [0.962s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRequestProcessing
| [0.963s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRead
| [1.140s] Microsoft.AspNetCore.Server.Kestrel Debug: InMemoryConnection.Dispose() started
| [1.140s] Microsoft.AspNetCore.Server.Kestrel Debug: InMemoryConnection.Dispose() complete
| [1.140s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting shutdown
| [1.140s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.StopProcessingNextRequest(Selected)
| [1.141s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.StopProcessingNextRequest()
| [6.344s] Microsoft.AspNetCore.Server.Kestrel Debug: Transport.Input.OnWriterCompleted fired
| [6.344s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.OnInputOrOutputCompleted(Selected)
| [6.344s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC7F149DOI" closing because: "The client closed the connection."
| [6.344s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC7F149DOI" disconnecting.
| [6.345s] Microsoft.AspNetCore.Server.Kestrel Debug: Result IsCompleted=True, IsCancelled=True 
| [6.345s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequests ended because endConnection=true
| [6.345s] Microsoft.AspNetCore.Server.Kestrel Debug: Transport.Output.OnReaderCompleted fired
| [6.345s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.OnInputOrOutputCompleted(Selected)
| [8.517s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to close gracefully during server shutdown.
| [8.520s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC7F149DOI" closing because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout."
| [8.526s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpProtocol.OnRequestProcessingEnded
| [9.723s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequestsAsync ended
| [9.731s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to abort during server shutdown.
| [9.734s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJC7F149DOI" stopped.
| [9.741s] TestLifetime Information: Finished test EmitsConnectionStartAndStop in 9.7383302s

davidfowl on 28 Dec 2018

Got some thread pool stats this time, looks like the CI machine is a 4 core machine and there are already 6 busy threads when that work item is being scheduled. I'm not sure if that's proof of anything but it takes 7 seconds to run the queued callback which is just insane.

| [0.001s] TestLifetime Information: Starting test EmitsConnectionStartAndStop at 2018-12-28T16:53:02
| [0.005s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting starting
| [0.005s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting started
| [0.006s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Loaded hosting startup assembly testhost
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJCSJN3UHI8" started.
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequestsAsync started
| [0.007s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequests started
| [0.007s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRequestProcessing
| [0.007s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRead
| [0.806s] Microsoft.AspNetCore.Server.Kestrel Debug: Result IsCompleted=False, IsCancelled=False 
| [0.806s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.1 GET http:///  
| [0.806s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJCSJN3UHI8" completed keep alive response.
| [0.806s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request finished in 0.6696ms 200 
| [0.807s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRequestProcessing
| [0.807s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRead
| [1.485s] Microsoft.AspNetCore.Server.Kestrel Debug: InMemoryConnection.Dispose() started
| [1.485s] Microsoft.AspNetCore.Server.Kestrel Debug: (Busy=6,Free=32761,Min=4,Max=32767)
| [1.485s] Microsoft.AspNetCore.Server.Kestrel Debug: InMemoryConnection.Dispose() complete
| [1.485s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting shutdown
| [1.486s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.StopProcessingNextRequest(Selected)
| [1.486s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.StopProcessingNextRequest()
| [8.237s] Microsoft.AspNetCore.Server.Kestrel Debug: Transport.Input.OnWriterCompleted fired
| [8.237s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.OnInputOrOutputCompleted(Selected)
| [8.237s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.OnInputOrOutputCompleted
| [8.237s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJCSJN3UHI8" closing because: "The client closed the connection."
| [8.237s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJCSJN3UHI8" disconnecting.
| [8.238s] Microsoft.AspNetCore.Server.Kestrel Debug: Result IsCompleted=True, IsCancelled=True 
| [8.238s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequests ended because endConnection=true
| [8.238s] Microsoft.AspNetCore.Server.Kestrel Debug: Transport.Output.OnReaderCompleted fired
| [8.238s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.OnInputOrOutputCompleted(Selected)
| [8.238s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.OnInputOrOutputCompleted
| [8.284s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to close gracefully during server shutdown.
| [8.287s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJCSJN3UHI8" closing because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout."
| [9.220s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.OnRequestProcessingEnded
| [9.795s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequestsAsync ended
| [9.797s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to abort during server shutdown.
| [9.802s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJCSJN3UHI8" stopped.
| [9.808s] TestLifetime Information: Finished test EmitsConnectionStartAndStop in 9.8071692s

davidfowl on 29 Dec 2018

Got more information and it seems like there are a considerable amount of work items queued just before we queue our 2 callbacks are queued to complete the pipe.

| [0.001s] TestLifetime Information: Starting test EmitsConnectionStartAndStop at 2018-12-29T12:51:38
| [0.004s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting starting
| [0.004s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting started
| [0.005s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Loaded hosting startup assembly testhost
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJDHHFKLD7F" started.
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequestsAsync started
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequests started
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRequestProcessing
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRead
| [0.471s] Microsoft.AspNetCore.Server.Kestrel Debug: Result IsCompleted=False, IsCancelled=False 
| [0.471s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.1 GET http:///  
| [0.471s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJDHHFKLD7F" completed keep alive response.
| [0.471s] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request finished in 0.6561ms 200 
| [0.472s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRequestProcessing
| [0.472s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.BeginRead
| [2.319s] Microsoft.AspNetCore.Server.Kestrel Debug: InMemoryConnection.Dispose() started
| [2.320s] Microsoft.AspNetCore.Server.Kestrel Debug: (WorkItems=79,Busy=7,Free=32760,Min=4,Max=32767)
| [2.320s] Microsoft.AspNetCore.Server.Kestrel Debug: InMemoryConnection.Dispose() complete
| [2.320s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting shutdown
| [2.320s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.StopProcessingNextRequest(Selected)
| [2.320s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.StopProcessingNextRequest()
| [5.817s] Microsoft.AspNetCore.Server.Kestrel Debug: Transport.Input.OnWriterCompleted fired
| [5.817s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.OnInputOrOutputCompleted(Selected)
| [5.817s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.OnInputOrOutputCompleted
| [5.817s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJDHHFKLD7F" closing because: "The client closed the connection."
| [5.817s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJDHHFKLD7F" disconnecting.
| [5.817s] Microsoft.AspNetCore.Server.Kestrel Debug: Result IsCompleted=True, IsCancelled=True 
| [5.817s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequests ended because endConnection=true
| [5.818s] Microsoft.AspNetCore.Server.Kestrel Debug: Transport.Output.OnReaderCompleted fired
| [5.818s] Microsoft.AspNetCore.Server.Kestrel Debug: HttpConnection.OnInputOrOutputCompleted(Selected)
| [5.818s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.OnInputOrOutputCompleted
| [7.575s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to close gracefully during server shutdown.
| [7.575s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJDHHFKLD7F" closing because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout."
| [8.083s] Microsoft.AspNetCore.Server.Kestrel Debug: Http1Connection.OnRequestProcessingEnded
| [8.592s] Microsoft.AspNetCore.Server.Kestrel Debug: Some connections failed to abort during server shutdown.
| [8.602s] Microsoft.AspNetCore.Server.Kestrel Debug: ProcessRequestsAsync ended
| [8.605s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLJDHHFKLD7F" stopped.
| [8.609s] TestLifetime Information: Finished test EmitsConnectionStartAndStop in 8.6083377s

davidfowl on 29 Dec 2018

Got a dump. TestServer.Dispose (in Kestrel) is the issue!