summerwind/h2spec

Infinite loop in VerifyConnectionError

Tratcher opened this issue · 6 comments

We use h2spec in our automated tests for ASP.NET Core's Kestrel HTTP/2 server. The client occasionally gets stuck in an infinite loop in VerifyConnectionError. The timeout setting does not work in this scenario, we have to apply our own that kills the client process after 30 seconds.

Here's a log that shows the client and server behavior. The test behaves as expected and the server closes the connection. The client then gets an error and loops endlessly.

2019-02-09T02:34:39.8786527Z   [xUnit.net 00:00:42.57]     RunIndividualTestCase(testCase: http2/4.3/3, HTTPS:False, Sends a HEADERS frame to another stream while sending the header blocks) [FAIL]
2019-02-09T02:35:14.2263772Z   Failed   RunIndividualTestCase(testCase: http2/4.3/3, HTTPS:False, Sends a HEADERS frame to another stream while sending the header blocks)
2019-02-09T02:35:14.2265139Z   Error Message:
2019-02-09T02:35:14.2266481Z    System.TimeoutException : h2spec didn't exit within 30 seconds.
2019-02-09T02:35:14.2266877Z   Stack Trace:
2019-02-09T02:35:14.2267479Z      at Interop.FunctionalTests.H2SpecCommands.RunTest(String testId, Int32 port, Boolean https, ILogger logger) in /_/src/Servers/Kestrel/test/Interop.FunctionalTests/H2SpecCommands.cs:line 225
2019-02-09T02:35:14.2268245Z      at Interop.FunctionalTests.H2SpecTests.RunIndividualTestCase(H2SpecTestCase testCase) in /_/src/Servers/Kestrel/test/Interop.FunctionalTests/H2SpecTests.cs:line 52
2019-02-09T02:35:14.2268915Z   --- End of stack trace from previous location where exception was thrown ---
2019-02-09T02:35:14.7012619Z   Standard Output Messages:
2019-02-09T02:35:14.9978804Z    | [0.001s] TestLifetime Information: Starting test RunIndividualTestCase-http2/4.3/3, HTTPS:False, Sends a HEADERS frame to another stream while sending the header blocks at 2019-02-09T02:34:09
2019-02-09T02:35:15.0018691Z    | [0.002s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting starting
2019-02-09T02:35:15.0034466Z    | [0.003s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting started
2019-02-09T02:35:15.0065632Z    | [0.003s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Loaded hosting startup assembly Interop.FunctionalTests
2019-02-09T02:35:15.0078218Z    | [0.058s] Interop.FunctionalTests.H2SpecTests Debug: Hypertext Transfer Protocol Version 2 (HTTP/2)
2019-02-09T02:35:15.0086390Z    | [0.060s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLKE6S61NCL3" started.
2019-02-09T02:35:15.0094188Z    | [0.062s] Interop.FunctionalTests.H2SpecTests Debug:   4. HTTP Frames
2019-02-09T02:35:15.0101296Z    | [0.062s] Interop.FunctionalTests.H2SpecTests Debug:     4.3. Header Compression and Decompression
2019-02-09T02:35:15.0109784Z    | [0.062s] Interop.FunctionalTests.H2SpecTests Debug:            [send] SETTINGS Frame (length:6, flags:0x00, stream_id:0)
2019-02-09T02:35:15.0117699Z    | [0.062s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "0HLKE6S61NCL3" sending SETTINGS frame for stream ID 0 with length 18 and flags NONE
2019-02-09T02:35:15.0125687Z    | [0.062s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "0HLKE6S61NCL3" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0
2019-02-09T02:35:15.0138673Z    | [0.062s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "0HLKE6S61NCL3" received SETTINGS frame for stream ID 0 with length 6 and flags NONE
2019-02-09T02:35:15.0153366Z    | [0.062s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] SETTINGS Frame (length:18, flags:0x00, stream_id:0)
2019-02-09T02:35:15.0164659Z    | [0.063s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "0HLKE6S61NCL3" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK
2019-02-09T02:35:15.0174787Z    | [0.063s] Interop.FunctionalTests.H2SpecTests Debug:            [send] SETTINGS Frame (length:0, flags:0x01, stream_id:0)
2019-02-09T02:35:15.0185840Z    | [0.063s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "0HLKE6S61NCL3" received SETTINGS frame for stream ID 0 with length 0 and flags ACK
2019-02-09T02:35:15.0194456Z    | [0.063s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] WINDOW_UPDATE Frame (length:4, flags:0x00, stream_id:0)
2019-02-09T02:35:15.0212247Z    | [0.063s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] SETTINGS Frame (length:0, flags:0x01, stream_id:0)
2019-02-09T02:35:15.0221798Z    | [0.063s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "0HLKE6S61NCL3" received HEADERS frame for stream ID 1 with length 16 and flags NONE
2019-02-09T02:35:15.0227797Z    | [0.063s] Interop.FunctionalTests.H2SpecTests Debug:            [send] HEADERS Frame (length:16, flags:0x00, stream_id:1)
2019-02-09T02:35:15.0231510Z    | [0.063s] Interop.FunctionalTests.H2SpecTests Debug:            [send] HEADERS Frame (length:4, flags:0x05, stream_id:3)
2019-02-09T02:35:15.0238248Z    | [0.063s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "0HLKE6S61NCL3" received HEADERS frame for stream ID 3 with length 4 and flags END_STREAM, END_HEADERS
2019-02-09T02:35:15.0244902Z    | [0.064s] Microsoft.AspNetCore.Server.Kestrel Information: Connection id "0HLKE6S61NCL3": HTTP/2 connection error.
2019-02-09T02:35:15.0252832Z    | Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2ConnectionErrorException: HTTP/2 connection error (PROTOCOL_ERROR): The client sent a HEADERS frame to stream ID 3 before signaling of the header block for stream ID 1.
2019-02-09T02:35:15.0256896Z    |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessHeadersFrameAsync[TContext](IHttpApplication`1 application, ReadOnlySequence`1 payload) in /_/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs:line 487
2019-02-09T02:35:15.0261630Z    |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessFrameAsync[TContext](IHttpApplication`1 application, ReadOnlySequence`1 payload) in /_/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs:line 410
2019-02-09T02:35:15.0263193Z    |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application) in /_/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs:line 306
2019-02-09T02:35:15.0274497Z    | [0.064s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLKE6S61NCL3" is closed. The last processed stream ID was 1.
2019-02-09T02:35:15.0319184Z    | [0.064s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "0HLKE6S61NCL3" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0
2019-02-09T02:35:15.0338233Z    | [0.064s] Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets Debug: Connection id "0HLKE6S61NCL3" sending FIN because: "The Socket transport's send loop completed gracefully."
2019-02-09T02:35:15.0344876Z    | [0.065s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HLKE6S61NCL3" stopped.
2019-02-09T02:35:15.0348639Z    | [0.102s] Interop.FunctionalTests.H2SpecTests Debug:            [send] CONTINUATION Frame (length:3512, flags:0x04, stream_id:1)
2019-02-09T02:35:15.0355131Z    | [0.103s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:35:15.0362897Z    | [0.103s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:35:15.0379015Z    | [0.103s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:35:15.0392690Z    | [0.103s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:35:15.0398480Z    | [0.103s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
... repeated a few thousand times
2019-02-09T02:36:24.3117269Z    | [29.999s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:36:24.3118781Z    | [30.000s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:36:24.3119660Z    | [30.000s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:36:24.3120918Z    | [30.000s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:36:24.3122019Z    | [30.000s] Interop.FunctionalTests.H2SpecTests Debug:            [recv] Error: read tcp 127.0.0.1:63806->127.0.0.1:63805: wsarecv: An established connection was aborted by the software in your host machine.
2019-02-09T02:36:24.3123038Z    | [30.013s] Microsoft.AspNetCore.Hosting.Internal.WebHost Debug: Hosting shutdown
2019-02-09T02:36:24.3124463Z    | [30.048s] TestLifetime Information: Finished test RunIndividualTestCase-http2/4.3/3, HTTPS:False, Sends a HEADERS frame to another stream while sending the header blocks in 30.0465251s

This maps to WSAECONNABORTED 10053 (0x2745) An established connection was aborted by the software in your host machine.

It looks like WaitEvent is only prepared to handle EOF and ECONNRESET. It should probobly assume all read errors are fatal here, no?

Thank you for the report!

It seems that this is a bug. I'm trying to fix the code, but it's hard to test due to I don't have a Windows environment. I have built a binary that contains fixes here. Can you try this?
h2spec_windows_amd64.zip

Thanks for the quick turnaround. Unfortunately it only repros in our automation environment where it's difficult to test private builds. I can test it locally to at least make sure it doesn't break normal usage.

This is working in local testing, thanks.

Thank you for the testing. I'm going to release a new version with fixes.

Fixes are released in v2.2.1. Please tell me if you still have a problem.
https://github.com/summerwind/h2spec/releases/tag/v2.2.1

It seems to be working, thanks.