[HTTP/3] New case of "The server returned an invalid or unrecognized response"

[CarnaViire]

Started happening after updating to 6.0.100-rc.1.21411.28
First noticed in stress tests here #57356 (comment)
But it is not specific to stress, neither to status code, so it is not the same as #55988

I am able to (rarely) reproduce it by serially calling GET requests (harder to repro with Kestrel's logging enabled)

HttpClient error looks like this

System.Net.Http.HttpRequestException : The server returned an invalid or unrecognized response.
      Stack Trace:
        C:\Users\knatalia\dev\git\runtime\src\libraries\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http3RequestStream.cs(318,0): at System.Net.Http.Http3RequestStream.ReadResponseAsync(CancellationToken cancellationToken)
        C:\Users\knatalia\dev\git\runtime\src\libraries\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http3RequestStream.cs(196,0): at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken)
        C:\Users\knatalia\dev\git\runtime\src\libraries\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http3RequestStream.cs(297,0): at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken)
        C:\Users\knatalia\dev\git\runtime\src\libraries\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http3Connection.cs(210,0): at System.Net.Http.Http3Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)

and related Kestrel log is

dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMB29L9PVOIV", Request id "0HMB29L9PVOIV:00000058": started reading request body.
dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMB29L9PVOIV", Request id "0HMB29L9PVOIV:00000058": done reading request body.
info: Microsoft.AspNetCore.Server.Kestrel[32]
      Connection id "0HMB29L9PVOIV", Request id "0HMB29L9PVOIV:00000058": the application completed without reading the entire request body.
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[13]
      Stream id "0HMB29L9PVOIV:00000058" read side aborted by application with error code 256 because: "The application completed without reading the entire request body.".
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMB29L9PVOIV:00000058" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMB29L9PVOIV:0000005C" type Bidirectional accepted.
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMB29L9PVOIV:0000005C" shutting down writes because: "The QUIC transport's send loop completed gracefully.".

I think the problem might be tied to "the application completed without reading the entire request body".
Kestrel did not call my callback for that request. All the times the error happened without Kestrel's logging enabled, I've also seen that my callback was not called but HttpClient received some response which it couldn't read.

For the record, Kestrel's callback is set up like this

var statuses = Enum.GetValues<HttpStatusCode>()
    .Where(s => s >= HttpStatusCode.OK) // exclude informational
    .Cast<int>().Distinct(); // remove dupes like Ambiguous(300) and MultipleChoices(300) to avoid ambiguous mapping
foreach (var status in statuses)
{    
    app.MapGet("/Expect" + status, () => {
        Console.WriteLine("GET request to /Expect" + status + ", will return " + status + " " + (HttpStatusCode)status);
        //return new StatusCodeResult(status);
        return Results.StatusCode(status);
    });
}

and HttpClient's requests are

            using HttpClient client = CreateHttpClient();

            var statuses = Enum.GetValues<HttpStatusCode>()
                .Where(s => s >= HttpStatusCode.OK) // exclude informational
                .Cast<int>().Distinct(); // remove dupes like Ambiguous(300) and MultipleChoices(300) to avoid ambiguous mapping
            foreach (var status in statuses)
            {    
                Console.WriteLine("Request expecting " + status + " " + (HttpStatusCode)status);
                using HttpRequestMessage request = new()
                {
                    Method = HttpMethod.Get,
                    RequestUri = new Uri("https://localhost:5001/Expect" + status),
                    Version = HttpVersion30,
                    VersionPolicy = HttpVersionPolicy.RequestVersionExact
                };
                using HttpResponseMessage response = await client.SendAsync(request).WaitAsync(TimeSpan.FromSeconds(10));
                
                if(status != (int)response.StatusCode)
                {
                    fail = true;
                    Console.WriteLine("    FAILURE -- received " + (int)response.StatusCode + " " + response.StatusCode);
                }
                else
                {
                    Console.WriteLine("    SUCCESS");
                }
            }

cc @JamesNK

[ghost]

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

Issue Details

---

Started happening after updating to 6.0.100-rc.1.21411.28
First noticed in stress tests here #57356 (comment)
But it is not specific to stress, neither to status code, so it is not the same as #55988

I am able to (rarely) reproduce it by serially calling GET requests (harder to repro with Kestrel's logging enabled)

HttpClient error looks like this

System.Net.Http.HttpRequestException : The server returned an invalid or unrecognized response.
      Stack Trace:
        C:\Users\knatalia\dev\git\runtime\src\libraries\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http3RequestStream.cs(318,0): at System.Net.Http.Http3RequestStream.ReadResponseAsync(CancellationToken cancellationToken)
        C:\Users\knatalia\dev\git\runtime\src\libraries\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http3RequestStream.cs(196,0): at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken)
        C:\Users\knatalia\dev\git\runtime\src\libraries\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http3RequestStream.cs(297,0): at System.Net.Http.Http3RequestStream.SendAsync(CancellationToken cancellationToken)
        C:\Users\knatalia\dev\git\runtime\src\libraries\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http3Connection.cs(210,0): at System.Net.Http.Http3Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)

and related Kestrel log is

dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMB29L9PVOIV", Request id "0HMB29L9PVOIV:00000058": started reading request body.
dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMB29L9PVOIV", Request id "0HMB29L9PVOIV:00000058": done reading request body.
info: Microsoft.AspNetCore.Server.Kestrel[32]
      Connection id "0HMB29L9PVOIV", Request id "0HMB29L9PVOIV:00000058": the application completed without reading the entire request body.
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[13]
      Stream id "0HMB29L9PVOIV:00000058" read side aborted by application with error code 256 because: "The application completed without reading the entire request body.".
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMB29L9PVOIV:00000058" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMB29L9PVOIV:0000005C" type Bidirectional accepted.
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMB29L9PVOIV:0000005C" shutting down writes because: "The QUIC transport's send loop completed gracefully.".

I think the problem might be tied to "the application completed without reading the entire request body".
Kestrel did not call my callback for that request. All the times the error happened without Kestrel's logging enabled, I've also seen that my callback was not called but HttpClient received some response which it couldn't read.

For the record, Kestrel's callback is set up like this

var statuses = Enum.GetValues<HttpStatusCode>()
    .Where(s => s >= HttpStatusCode.OK) // exclude informational
    .Cast<int>().Distinct(); // remove dupes like Ambiguous(300) and MultipleChoices(300) to avoid ambiguous mapping
foreach (var status in statuses)
{    
    app.MapGet("/Expect" + status, () => {
        Console.WriteLine("GET request to /Expect" + status + ", will return " + status + " " + (HttpStatusCode)status);
        //return new StatusCodeResult(status);
        return Results.StatusCode(status);
    });
}

and HttpClient's requests are

            using HttpClient client = CreateHttpClient();

            var statuses = Enum.GetValues<HttpStatusCode>()
                .Where(s => s >= HttpStatusCode.OK) // exclude informational
                .Cast<int>().Distinct(); // remove dupes like Ambiguous(300) and MultipleChoices(300) to avoid ambiguous mapping
            foreach (var status in statuses)
            {    
                Console.WriteLine("Request expecting " + status + " " + (HttpStatusCode)status);
                using HttpRequestMessage request = new()
                {
                    Method = HttpMethod.Get,
                    RequestUri = new Uri("https://localhost:5001/Expect" + status),
                    Version = HttpVersion30,
                    VersionPolicy = HttpVersionPolicy.RequestVersionExact
                };
                using HttpResponseMessage response = await client.SendAsync(request).WaitAsync(TimeSpan.FromSeconds(10));
                
                if(status != (int)response.StatusCode)
                {
                    fail = true;
                    Console.WriteLine("    FAILURE -- received " + (int)response.StatusCode + " " + response.StatusCode);
                }
                else
                {
                    Console.WriteLine("    SUCCESS");
                }
            }

cc @JamesNK

Author:	CarnaViire
Assignees:	-
Labels:	area-System.Net.Http, untriaged
Milestone:	-

[CarnaViire]

@JamesNK in what situation can "the application completed without reading the entire request body" happen? What does this mean and why the callback was not called?

[ManickaP]

@CarnaViire could you in your test catch the exception from the client and continue sending additional requests? I'd like to confirm/deny my theory with another type of errors seen in the stress.
I'm looking for System.Net.Quic.QuicConnectionAbortedException: Connection aborted by peer (0). after the The server returned an invalid or unrecognized response. because it seems to me that the server will close the connection right after the first problem, causing even more issues within the stress test.

[JamesNK]

I think this is an issue in Kestrel and will be fixed with dotnet/aspnetcore#35434

@JamesNK in what situation can "the application completed without reading the entire request body" happen? What does this mean and why the callback was not called?

It happens if the request body isn't read until the end. The logs indicate you have started reading it, but not until the end.

You can work around this bug by reading the request body in Kestrel until the end. Edit: Can also be caused by race condition with end stream flag. Should be resolved with addition of ReadsCompleted.

[CarnaViire]

@ManickaP you are right. On the next request after The server returned an invalid or unrecognized response. I got QuicConnectionAbortedException: Connection aborted by peer (0). The following requests were fine.

[ManickaP]

Thanks for confirmation @CarnaViire, I filed another issue in ASP dotnet/aspnetcore#35470.

[CarnaViire]

To sum up, we expect this issue to get resolved after dotnet/aspnetcore#35434, dotnet/aspnetcore#35470 and dotnet/aspnetcore#35399 get fixed/merged.

[karelz]

@CarnaViire both issues are now merged. I guess we can close this issue and unblock our Stress.
cc @ManickaP

[CarnaViire]

Today's stress run still has the issue (System.Net.Http.HttpRequestException: The server returned an invalid or unrecognized response.) https://dev.azure.com/dnceng/public/_build/results?buildId=1311648&view=logs&j=0da5d1d9-276d-5173-c4c4-9d4d4ed14fdb&t=1451f5f3-0108-5a08-5b92-e984b2a85bbd
ASP.NET Core version is 6.0.0-rc.1.21419.28
@JamesNK do you know if this version includes both fixes?

[JamesNK]

I don't think so.

It's 4 days old - dotnet/sdk#19917
These changes were merged into 6.0-rc1 3 days ago - https://github.com/dotnet/aspnetcore/commits/release/6.0-rc1

[JamesNK]

The stress runs on that environment have used an older SDK over the last couple of days. You should investigate why and get it to use the latest SDK.

[ManickaP]

We're running in the nightly docker image and that hasn't been updated yet, i.e.: https://github.com/dotnet/dotnet-docker/blob/nightly/src/runtime/6.0/bullseye-slim/amd64/Dockerfile
Note that there's a PR up with an update: dotnet/dotnet-docker#3069

[ManickaP]

This particular issue is fixed, H/3 stress runs for 30 mins, no occurrences of this error, closing.
Other errors do happen, but we track that elsewhere.

[karelz]

Addressed in 6.0, reflecting that in the milestone.