Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[HTTP/3] The server returned an invalid or unrecognized response. #55988

Closed
JamesNK opened this issue Jul 20, 2021 · 8 comments · Fixed by #57236
Closed

[HTTP/3] The server returned an invalid or unrecognized response. #55988

JamesNK opened this issue Jul 20, 2021 · 8 comments · Fixed by #57236
Assignees
@CarnaViire
Labels
area-System.Net.Http bug
Milestone
6.0.0

Comments

@JamesNK
Copy link
Member

JamesNK commented Jul 20, 2021 •
edited
Loading

I have a gRPC call that uses HTTP/3 and it is erroring because of the response.

I tried to figure out why HttpClient is rejecting the response so I enabled Kestrel connection logging and client event source. This seems to be the specific problem:

<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,27858262,0,ReadResponseAsync,Expected HEADERS as first response frame; received . ->

Complete logs below. As far as I can tell Kestrel is sending a HEADERS frame and HttpClient seems to have a problem reading it. I don't know if that is because Kestrel is doing something wrong or HttpClient is.

 SendUnauthenticatedRequest_UnauthenticatedErrorResponse
   Source: AuthTests.cs line 104
   Duration: 489 ms

  Message: 
  Expected: Unauthenticated
  But was:  Internal

TearDown : System.Exception : 1 error(s) logged.
Grpc.Net.Client.Internal.GrpcCall - ErrorStartingCall - Error starting gRPC call.
===================
System.Net.Http.HttpRequestException: The server returned an invalid or unrecognized response.
   at System.Net.Http.Http3RequestStream.ReadResponseAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c3+0x115
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x444
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x77c
   at System.Net.Http.Http3Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600068e+0x232
   at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000742+0x1a1
   at System.Net.Http.HttpConnectionPool.DetermineVersionAndSendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000745+0xa7
   at System.Net.Http.HttpConnectionPool.SendAndProcessAltSvcAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000746+0x8e
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000747+0x99
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600088e+0x14f
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60007f6+0x94
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in System.Net.Http.dll:token 0x6000264+0xae
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Internal\GrpcCall.cs:line 441
===================

  Stack Trace: 
AuthTests.SendUnauthenticatedRequest_UnauthenticatedErrorResponse() line 131
framework.dll:token 0x6000d7a+0x7
framework.dll:token 0x6000d33+0x1
framework.dll:token 0x60003e4+0x34
framework.dll:token 0x6000839+0x3b
framework.dll:token 0x6000838+0x1
framework.dll:token 0x6000e09+0x18
framework.dll:token 0x6000815+0x2
--TearDown
VerifyNoErrorsScope.Dispose() line 82
GrpcTestContext.Dispose() line 106
FunctionalTestBase.TearDown() line 103

  Standard Output: 
0.004s GrpcTestContext - Information: Starting AuthTests.SendUnauthenticatedRequest_UnauthenticatedErrorResponse
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpClientHandler#22036639,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : SocketsHttpHandler#23095417,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : Http3DelegatingHandler#24807124,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : Http3DelegatingHandler#24807124,InnerHandler,Http3DelegatingHandler#24807124,HttpClientHandler#22036639 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpClient#1850352,.ctor,HttpClient#1850352,Http3DelegatingHandler#24807124 ->
<- Event Private.InternalDiagnostics.System.Net.Http - UriBaseAddress : https://127.0.0.1:50010/,HttpClient#1850352,1850352 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : PushUnaryContent`2#28828555,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#54860159,Content,HttpRequestMessage#54860159,PushUnaryContent`2#28828555 ->
0.057s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'Unary', URI: 'https://127.0.0.1:50010/authorize.AuthorizedGreeter/SayHello'.
<- Event System.Net.Http - RequestStart : https,127.0.0.1,50010,/authorize.AuthorizedGreeter/SayHello,2,0,1 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#9140582,.ctor,AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null) ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#9140582,.ctor,_useProxy=True ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#9140582,TryCreate,AutoSettingsUsed, calling WinHttpOpen ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#57266958,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#31364791,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#25445537,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : WinInetProxyHelper#9140582,GetProxyForUrl,error=12180 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#9140582,GetProxyForUrl,useProxy=False ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,0,0,.ctor,HttpConnectionPool https://127.0.0.1:50010 ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5560867,.ctor,[conn][0x2B924849FD0] Outbound connection created ->
0.117s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMABBQ559FOE" accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11865849,.ctor,[strm][0x2B924A155F0] Outbound unidirectional stream created in connection [conn][0x2B924849FD0]. ->
0.123s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMABBQ559FOE" accepted.
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
0.124s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMABBQ559FOE" started.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,.ctor,[strm][0x2B924A17BA0] Outbound bidirectional stream created in connection [conn][0x2B924849FD0]. ->
0.134s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.141s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Authorize.HelloRequest' to 6 byte message.
0.145s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,ReadAsync,[strm][0x2B924A17BA0] Stream reading into Memory of '64' bytes. ->
0.155s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMABBQ559FOE:3" type Unidirectional connected.
0.172s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: WriteAsync[1]
00                                                 .
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x2B924AB3EC0] Stream reading into Memory of '32' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x2B924AB3EC0] Stream reading into Memory of '32' bytes. ->
0.181s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: WriteAsync[7]
04 05 06 80 00 80 00                               .......
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x2B924AB3EC0] Stream reading into Memory of '32' bytes. ->
0.189s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMABBQ559FOE:2" type Unidirectional accepted.
0.190s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMABBQ559FOE:0" type Bidirectional accepted.
0.196s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: ReadAsync[8]
00 04 05 06 80 01 00 00                            ........ 
0.203s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMABBQ559FOE:2" received SETTINGS frame for stream ID 2 with length 5.
0.206s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: ReadAsync[261]
01 40 F5 00 00 D4 D7 50  0F 31 32 37 2E 30 2E 30   .@õ..Ô×P .127.0.0
2E 31 3A 35 30 30 31 30  51 25 2F 61 75 74 68 6F   .1:50010 Q%/autho
72 69 7A 65 2E 41 75 74  68 6F 72 69 7A 65 64 47   rize.Aut horizedG
72 65 65 74 65 72 2F 53  61 79 48 65 6C 6C 6F 37   reeter/S ayHello7
01 61 6C 74 2D 75 73 65  64 0F 31 32 37 2E 30 2E   .alt-use d.127.0.
30 2E 31 3A 35 30 30 31  30 7F 50 14 67 72 70 63   0.1:5001 0.P.grpc
2D 64 6F 74 6E 65 74 2F  32 2E 33 38 2E 30 2E 30   -dotnet/ 2.38.0.0
32 74 65 08 74 72 61 69  6C 65 72 73 37 0D 67 72   2te.trai lers7.gr
70 63 2D 61 63 63 65 70  74 2D 65 6E 63 6F 64 69   pc-accep t-encodi
6E 67 0D 69 64 65 6E 74  69 74 79 2C 67 7A 69 70   ng.ident ity,gzip
37 04 74 72 61 63 65 70  61 72 65 6E 74 37 30 30   7.tracep arent700
2D 62 66 33 38 36 33 34  31 66 33 31 31 36 34 33   -bf38634 1f311643
37 64 38 65 35 36 31 36  35 37 35 32 36 65 34 63   7d8e5616 57526e4c
35 2D 32 66 34 30 66 32  63 63 36 66 31 39 30 35   5-2f40f2 cc6f1905
30 36 2D 30 30 7F 1D 10  61 70 70 6C 69 63 61 74   06-00... applicat
69 6F 6E 2F 67 72 70 63  00 0B 00 00 00 00 06 0A   ion/grpc ........
04 74 65 73 74                                     .test
0.206s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMABBQ559FOE:0" received HEADERS frame for stream ID 0 with length 245.
0.230s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMABBQ559FOE:0" received DATA frame for stream ID 0 with length 11.
0.231s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: ReadAsync[0]
0.258s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50010/authorize.AuthorizedGreeter/SayHello application/grpc -
0.310s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /authorize.AuthorizedGreeter/SayHello'
0.348s SERVER Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler - Debug: AuthenticationScheme: Bearer was not authenticated.
0.351s SERVER Microsoft.AspNetCore.Authorization.DefaultAuthorizationService - Information: Authorization failed. These requirements were not met:
ClaimsAuthorizationRequirement:Claim.Type=http://schemas.xmlsoap.org/ws/2005/05/identity/claims/name
0.367s SERVER Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler - Information: AuthenticationScheme: Bearer was challenged.
0.381s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMABBQ559FOE:0" sending HEADERS frame for stream ID 0 with length 101.
0.384s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: WriteAsync[104]
01 40 65 00 00 5F 30 03  34 30 31 34 64 61 74 65   .@e.._0. 4014date
1D 54 75 65 2C 20 32 30  20 4A 75 6C 20 32 30 32   .Tue, 20  Jul 202
31 20 30 39 3A 31 32 3A  34 36 20 47 4D 54 36 73   1 09:12: 46 GMT6s
65 72 76 65 72 07 4B 65  73 74 72 65 6C 37 09 77   erver.Ke strel7.w
77 77 2D 61 75 74 68 65  6E 74 69 63 61 74 65 06   ww-authe nticate.
42 65 61 72 65 72 37 07  63 6F 6E 74 65 6E 74 2D   Bearer7. content-
6C 65 6E 67 74 68 01 30                            length.0 
0.387s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/3 POST https://127.0.0.1:50010/authorize.AuthorizedGreeter/SayHello application/grpc - - 401 0 - 128.9380ms
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,27858262,0,ReadFrameEnvelopeAsync,Received frame 1 of length 101. ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#22877577,RequestMessage,HttpResponseMessage#22877577,HttpRequestMessage#54860159 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#47259456,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#22877577,Content,HttpResponseMessage#22877577,HttpConnectionResponseContent#47259456 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,ReadAsync,[strm][0x2B924A17BA0] Stream reading into Memory of '64' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,ReadAsync,[strm][0x2B924A17BA0] Stream reading into Memory of '64' bytes. ->
0.390s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMABBQ559FOE:0", Request id "0HMABBQ559FOE:0": started reading request body.
0.391s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMABBQ559FOE:0", Request id "0HMABBQ559FOE:0": done reading request body.
0.396s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMABBQ559FOE:0" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,27858262,0,ReadResponseAsync,Expected HEADERS as first response frame; received . ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,Dispose,[strm][0x2B924A17BA0] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,Cleanup,[strm][0x2B924A17BA0] releasing handles. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,Dispose,[strm][0x2B924A17BA0] Stream disposed ->
<- Event System.Net.Http - RequestFailed :  ->
<- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : HttpClient#1850352,HandleFailure,System.Net.Http.HttpRequestException: The server returned an invalid or unrecognized response.
   at System.Net.Http.Http3RequestStream.ReadResponseAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c3+0x115
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x444
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x77c
   at System.Net.Http.Http3Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600068e+0x232
   at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000742+0x1a1
   at System.Net.Http.HttpConnectionPool.DetermineVersionAndSendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000745+0xa7
   at System.Net.Http.HttpConnectionPool.SendAndProcessAltSvcAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000746+0x8e
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000747+0x99
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600088e+0x14f
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60007f6+0x94
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in System.Net.Http.dll:token 0x6000264+0xae ->
<- Event System.Net.Http - RequestStop :  ->
0.418s Grpc.Net.Client.Internal.GrpcCall - Error: Error starting gRPC call.
System.Net.Http.HttpRequestException: The server returned an invalid or unrecognized response.
   at System.Net.Http.Http3RequestStream.ReadResponseAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c3+0x115
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x444
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x77c
   at System.Net.Http.Http3Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600068e+0x232
   at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000742+0x1a1
   at System.Net.Http.HttpConnectionPool.DetermineVersionAndSendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000745+0xa7
   at System.Net.Http.HttpConnectionPool.SendAndProcessAltSvcAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000746+0x8e
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000747+0x99
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600088e+0x14f
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60007f6+0x94
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in System.Net.Http.dll:token 0x6000264+0xae
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Internal\GrpcCall.cs:line 441
0.429s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. HttpRequestException: The server returned an invalid or unrecognized response.'.
0.430s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.431s Grpc.Net.Client.Internal.GrpcCall - Debug: gRPC call canceled.
0.474s GrpcTestContext - Information: Finishing AuthTests.SendUnauthenticatedRequest_UnauthenticatedErrorResponse

Repo: https://github.com/JamesNK/grpc-dotnet/tree/jamesnk/http3-badresponse
Test: AuthTests.SendUnauthenticatedRequest_UnauthenticatedErrorResponse (Note this type is parameterized. Need to run Http3WithTls)

.NET SDK (reflecting any global.json):
 Version:   6.0.100-rc.1.21368.1
 Commit:    a5889518cc
@ghost
Copy link

ghost commented Jul 20, 2021

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

Issue Details

I have a gRPC call that uses HTTP/3 and it is erroring because of the response.

I tried to figure out why HttpClient is rejecting the response so I enabled Kestrel connection logging and client event source. This seems to be the specific problem:

<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,27858262,0,ReadResponseAsync,Expected HEADERS as first response frame; received . ->

Complete logs below. As far as I can tell Kestrel is sending a HEADERS frame and HttpClient seems to have a problem reading it. I don't know if that is because Kestrel is doing something wrong or HttpClient is.

 SendUnauthenticatedRequest_UnauthenticatedErrorResponse
   Source: AuthTests.cs line 104
   Duration: 489 ms

  Message: 
  Expected: Unauthenticated
  But was:  Internal

TearDown : System.Exception : 1 error(s) logged.
Grpc.Net.Client.Internal.GrpcCall - ErrorStartingCall - Error starting gRPC call.
===================
System.Net.Http.HttpRequestException: The server returned an invalid or unrecognized response.
   at System.Net.Http.Http3RequestStream.ReadResponseAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c3+0x115
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x444
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x77c
   at System.Net.Http.Http3Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600068e+0x232
   at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000742+0x1a1
   at System.Net.Http.HttpConnectionPool.DetermineVersionAndSendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000745+0xa7
   at System.Net.Http.HttpConnectionPool.SendAndProcessAltSvcAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000746+0x8e
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000747+0x99
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600088e+0x14f
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60007f6+0x94
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in System.Net.Http.dll:token 0x6000264+0xae
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Internal\GrpcCall.cs:line 441
===================

  Stack Trace: 
AuthTests.SendUnauthenticatedRequest_UnauthenticatedErrorResponse() line 131
framework.dll:token 0x6000d7a+0x7
framework.dll:token 0x6000d33+0x1
framework.dll:token 0x60003e4+0x34
framework.dll:token 0x6000839+0x3b
framework.dll:token 0x6000838+0x1
framework.dll:token 0x6000e09+0x18
framework.dll:token 0x6000815+0x2
--TearDown
VerifyNoErrorsScope.Dispose() line 82
GrpcTestContext.Dispose() line 106
FunctionalTestBase.TearDown() line 103

  Standard Output: 
0.004s GrpcTestContext - Information: Starting AuthTests.SendUnauthenticatedRequest_UnauthenticatedErrorResponse
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpClientHandler#22036639,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : SocketsHttpHandler#23095417,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : Http3DelegatingHandler#24807124,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : Http3DelegatingHandler#24807124,InnerHandler,Http3DelegatingHandler#24807124,HttpClientHandler#22036639 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpClient#1850352,.ctor,HttpClient#1850352,Http3DelegatingHandler#24807124 ->
<- Event Private.InternalDiagnostics.System.Net.Http - UriBaseAddress : https://127.0.0.1:50010/,HttpClient#1850352,1850352 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : PushUnaryContent`2#28828555,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#54860159,Content,HttpRequestMessage#54860159,PushUnaryContent`2#28828555 ->
0.057s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'Unary', URI: 'https://127.0.0.1:50010/authorize.AuthorizedGreeter/SayHello'.
<- Event System.Net.Http - RequestStart : https,127.0.0.1,50010,/authorize.AuthorizedGreeter/SayHello,2,0,1 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#9140582,.ctor,AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null) ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#9140582,.ctor,_useProxy=True ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#9140582,TryCreate,AutoSettingsUsed, calling WinHttpOpen ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#57266958,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#31364791,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#25445537,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : WinInetProxyHelper#9140582,GetProxyForUrl,error=12180 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#9140582,GetProxyForUrl,useProxy=False ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,0,0,.ctor,HttpConnectionPool https://127.0.0.1:50010 ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5560867,.ctor,[conn][0x2B924849FD0] Outbound connection created ->
0.117s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMABBQ559FOE" accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11865849,.ctor,[strm][0x2B924A155F0] Outbound unidirectional stream created in connection [conn][0x2B924849FD0]. ->
0.123s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMABBQ559FOE" accepted.
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
0.124s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMABBQ559FOE" started.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,.ctor,[strm][0x2B924A17BA0] Outbound bidirectional stream created in connection [conn][0x2B924849FD0]. ->
0.134s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.141s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Authorize.HelloRequest' to 6 byte message.
0.145s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,ReadAsync,[strm][0x2B924A17BA0] Stream reading into Memory of '64' bytes. ->
0.155s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMABBQ559FOE:3" type Unidirectional connected.
0.172s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: WriteAsync[1]
00                                                 .
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x2B924AB3EC0] Stream reading into Memory of '32' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x2B924AB3EC0] Stream reading into Memory of '32' bytes. ->
0.181s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: WriteAsync[7]
04 05 06 80 00 80 00                               .......
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x2B924AB3EC0] Stream reading into Memory of '32' bytes. ->
0.189s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMABBQ559FOE:2" type Unidirectional accepted.
0.190s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMABBQ559FOE:0" type Bidirectional accepted.
0.196s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: ReadAsync[8]
00 04 05 06 80 01 00 00                            ........ 
0.203s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMABBQ559FOE:2" received SETTINGS frame for stream ID 2 with length 5.
0.206s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: ReadAsync[261]
01 40 F5 00 00 D4 D7 50  0F 31 32 37 2E 30 2E 30   .@õ..Ô×P .127.0.0
2E 31 3A 35 30 30 31 30  51 25 2F 61 75 74 68 6F   .1:50010 Q%/autho
72 69 7A 65 2E 41 75 74  68 6F 72 69 7A 65 64 47   rize.Aut horizedG
72 65 65 74 65 72 2F 53  61 79 48 65 6C 6C 6F 37   reeter/S ayHello7
01 61 6C 74 2D 75 73 65  64 0F 31 32 37 2E 30 2E   .alt-use d.127.0.
30 2E 31 3A 35 30 30 31  30 7F 50 14 67 72 70 63   0.1:5001 0.P.grpc
2D 64 6F 74 6E 65 74 2F  32 2E 33 38 2E 30 2E 30   -dotnet/ 2.38.0.0
32 74 65 08 74 72 61 69  6C 65 72 73 37 0D 67 72   2te.trai lers7.gr
70 63 2D 61 63 63 65 70  74 2D 65 6E 63 6F 64 69   pc-accep t-encodi
6E 67 0D 69 64 65 6E 74  69 74 79 2C 67 7A 69 70   ng.ident ity,gzip
37 04 74 72 61 63 65 70  61 72 65 6E 74 37 30 30   7.tracep arent700
2D 62 66 33 38 36 33 34  31 66 33 31 31 36 34 33   -bf38634 1f311643
37 64 38 65 35 36 31 36  35 37 35 32 36 65 34 63   7d8e5616 57526e4c
35 2D 32 66 34 30 66 32  63 63 36 66 31 39 30 35   5-2f40f2 cc6f1905
30 36 2D 30 30 7F 1D 10  61 70 70 6C 69 63 61 74   06-00... applicat
69 6F 6E 2F 67 72 70 63  00 0B 00 00 00 00 06 0A   ion/grpc ........
04 74 65 73 74                                     .test
0.206s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMABBQ559FOE:0" received HEADERS frame for stream ID 0 with length 245.
0.230s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMABBQ559FOE:0" received DATA frame for stream ID 0 with length 11.
0.231s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: ReadAsync[0]
0.258s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50010/authorize.AuthorizedGreeter/SayHello application/grpc -
0.310s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /authorize.AuthorizedGreeter/SayHello'
0.348s SERVER Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler - Debug: AuthenticationScheme: Bearer was not authenticated.
0.351s SERVER Microsoft.AspNetCore.Authorization.DefaultAuthorizationService - Information: Authorization failed. These requirements were not met:
ClaimsAuthorizationRequirement:Claim.Type=http://schemas.xmlsoap.org/ws/2005/05/identity/claims/name
0.367s SERVER Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler - Information: AuthenticationScheme: Bearer was challenged.
0.381s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMABBQ559FOE:0" sending HEADERS frame for stream ID 0 with length 101.
0.384s SERVER Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware - Debug: WriteAsync[104]
01 40 65 00 00 5F 30 03  34 30 31 34 64 61 74 65   .@e.._0. 4014date
1D 54 75 65 2C 20 32 30  20 4A 75 6C 20 32 30 32   .Tue, 20  Jul 202
31 20 30 39 3A 31 32 3A  34 36 20 47 4D 54 36 73   1 09:12: 46 GMT6s
65 72 76 65 72 07 4B 65  73 74 72 65 6C 37 09 77   erver.Ke strel7.w
77 77 2D 61 75 74 68 65  6E 74 69 63 61 74 65 06   ww-authe nticate.
42 65 61 72 65 72 37 07  63 6F 6E 74 65 6E 74 2D   Bearer7. content-
6C 65 6E 67 74 68 01 30                            length.0 
0.387s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/3 POST https://127.0.0.1:50010/authorize.AuthorizedGreeter/SayHello application/grpc - - 401 0 - 128.9380ms
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,27858262,0,ReadFrameEnvelopeAsync,Received frame 1 of length 101. ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#22877577,RequestMessage,HttpResponseMessage#22877577,HttpRequestMessage#54860159 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#47259456,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#22877577,Content,HttpResponseMessage#22877577,HttpConnectionResponseContent#47259456 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,ReadAsync,[strm][0x2B924A17BA0] Stream reading into Memory of '64' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,ReadAsync,[strm][0x2B924A17BA0] Stream reading into Memory of '64' bytes. ->
0.390s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMABBQ559FOE:0", Request id "0HMABBQ559FOE:0": started reading request body.
0.391s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMABBQ559FOE:0", Request id "0HMABBQ559FOE:0": done reading request body.
0.396s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMABBQ559FOE:0" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 55334867,27858262,0,ReadResponseAsync,Expected HEADERS as first response frame; received . ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,Dispose,[strm][0x2B924A17BA0] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,Cleanup,[strm][0x2B924A17BA0] releasing handles. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,Dispose,[strm][0x2B924A17BA0] Stream disposed ->
<- Event System.Net.Http - RequestFailed :  ->
<- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : HttpClient#1850352,HandleFailure,System.Net.Http.HttpRequestException: The server returned an invalid or unrecognized response.
   at System.Net.Http.Http3RequestStream.ReadResponseAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c3+0x115
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x444
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x77c
   at System.Net.Http.Http3Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600068e+0x232
   at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000742+0x1a1
   at System.Net.Http.HttpConnectionPool.DetermineVersionAndSendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000745+0xa7
   at System.Net.Http.HttpConnectionPool.SendAndProcessAltSvcAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000746+0x8e
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000747+0x99
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600088e+0x14f
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60007f6+0x94
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in System.Net.Http.dll:token 0x6000264+0xae ->
<- Event System.Net.Http - RequestStop :  ->
0.418s Grpc.Net.Client.Internal.GrpcCall - Error: Error starting gRPC call.
System.Net.Http.HttpRequestException: The server returned an invalid or unrecognized response.
   at System.Net.Http.Http3RequestStream.ReadResponseAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c3+0x115
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x444
   at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60006c2+0x77c
   at System.Net.Http.Http3Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600068e+0x232
   at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000742+0x1a1
   at System.Net.Http.HttpConnectionPool.DetermineVersionAndSendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000745+0xa7
   at System.Net.Http.HttpConnectionPool.SendAndProcessAltSvcAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000746+0x8e
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x6000747+0x99
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x600088e+0x14f
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in System.Net.Http.dll:token 0x60007f6+0x94
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in System.Net.Http.dll:token 0x6000264+0xae
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Internal\GrpcCall.cs:line 441
0.429s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. HttpRequestException: The server returned an invalid or unrecognized response.'.
0.430s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.431s Grpc.Net.Client.Internal.GrpcCall - Debug: gRPC call canceled.
0.474s GrpcTestContext - Information: Finishing AuthTests.SendUnauthenticatedRequest_UnauthenticatedErrorResponse

Repo: https://github.com/JamesNK/grpc-dotnet/tree/jamesnk/http3-badresponse
Test: AuthTests.SendUnauthenticatedRequest_UnauthenticatedErrorResponse (Note this type is parameterized. Need to run Http3WithTls)

Author: JamesNK
Assignees: -
Labels:

area-System.Net.Http
Milestone: -

@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Jul 20, 2021
@karelz karelz changed the title HTTP/3: The server returned an invalid or unrecognized response. [HTTP/3] The server returned an invalid or unrecognized response. Jul 20, 2021
@karelz karelz added this to the 6.0.0 milestone Jul 20, 2021
@karelz karelz added bug and removed untriaged New issue has not been triaged by the area owner labels Jul 20, 2021
@karelz
Copy link
Member

karelz commented Jul 20, 2021

Triage: Looks pretty bad, we should root cause, then decide what to do about it.

@ManickaP ManickaP removed their assignment Jul 22, 2021
@karelz
Copy link
Member

karelz commented Jul 22, 2021

Triage: 100% repro on this type of request.

@JamesNK
Copy link
Member Author

JamesNK commented Jul 30, 2021

I looked into this more and have narrowed down the cause to the status code.

The server returned an invalid or unrecognized response for 415:

endpoints.MapPost("/ThisIsATest", context =>
{
    context.Response.StatusCode = 415;
    return Task.CompletedTask;
});

Success for 200:

endpoints.MapPost("/ThisIsATest", context =>
{
    context.Response.StatusCode = 200;
    return Task.CompletedTask;
});

The question is, is there a bug in how Kestrel writes the status code, or a bug in how HttpClient reads it?

@wfurt
Copy link
Member

wfurt commented Jul 30, 2021

If we get hands on session keys and/or sever key and if we can collect packecpature we should be able to peak in, right?
Would tracing help to see what server is intending to send for given request vs what is sending? And add some unique ID to the url so it is easier to correlate.

@JamesNK
Copy link
Member Author

JamesNK commented Jul 30, 2021 •
edited
Loading

I'm pretty sure the problem is in HttpClient.

I tested Kestrel with curl + http3. curl recognises the 415 status.

C:\Users\jamesnk.SOUTHPACIFIC> docker run -it --rm ymuski/curl-http3 curl -IL https://host.docker.internal:5557 --http3
HTTP/3 415
date: Fri, 30 Jul 2021 01:51:57 GMT
server: Kestrel
test: foo

I think you need to add some tests of HttpClient loading HTTP/3 responses with 415 statuses to find out what is going on. The error may be happening because the 415 status isn't in the static table, unlike 200 and other common statuses.

@CarnaViire CarnaViire self-assigned this Aug 6, 2021
@ManickaP
Copy link
Member

Triage: we should support static QPACK, we should be sure we support other than well-defined status codes in QPACK.
To confirm, we should get rid of the 100-continue on the server side. We should also look into QPACK test and see if we can add a test here to simulate the status code problem to at least confirm or disprove whether we can handle it.

@CarnaViire
Copy link
Member

It is a bug in our QPACK code (so it was not Kestrel sending 100, but us misinterpreting "Literal Field Line With Name Reference" path). I will put up a PR with a fix tomorrow.

@CarnaViire CarnaViire mentioned this issue Aug 11, 2021
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Aug 11, 2021
CarnaViire added a commit that referenced this issue Aug 12, 2021
@CarnaViire
Fix QPACK status decode (#57236)
d27eb8d 
Fix "Literal Header Field With Name Reference" parsing for Status code. Add tests for QPACK-ed and not QPACK-ed status receiving for all status codes (except informational).

Fix QPackStaticTable.HeaderLookup to comply with spec (the order was off, so lookup didn't work correctly in some cases).

Fixes #55988
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Aug 12, 2021
@ManickaP ManickaP mentioned this issue Aug 13, 2021
Merged
@CarnaViire CarnaViire mentioned this issue Aug 18, 2021
Closed
@ghost ghost locked as resolved and limited conversation to collaborators Sep 11, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@CarnaViire CarnaViire

Labels
area-System.Net.Http bug
Projects
None yet
Milestone
6.0.0
Development

Successfully merging a pull request may close this issue.

[HTTP/3] Fix QPACK status decode CarnaViire/runtime
5 participants
@JamesNK @CarnaViire @karelz @ManickaP @wfurt