[7.0 preview 1] HTTP DELETE sometimes treated as HTTP POST

[martincostello]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

This is a bit of a weird one, and I'm not sure exactly what's at fault, but code that works fine with ASP.NET Core 6 is not working some of the time with ASP.NET Core 7 preview 1.

Testing a sample app of mine with preview 1 is getting test failures in UI tests that attempt to delete items from a Razor Pages UI using some Minimal API endpoints. The upgrade PR illustrating the issue is here: martincostello/dotnet-minimal-api-integration-testing#257.

Some UI tests fail in GitHub Actions on Linux and Windows, but none of the UI tests on macOS do.

Debugging this locally on my Windows 11 laptop, I've been able to fairly reliably repo the issue with Firefox but not with Chrome.

The behaviour is that attempting to delete a second Todo item from the application via the UI fails with an HTTP 400 error, which appears to be coming from anti-forgery.

Turning up logging and looking at the Network tab in Firefox appears to show that the second HTTP DELETE request from the browser is being interpreted by the app as an HTTP POST, which then doesn't match the Minimal API delete endpoint, and then goes through into MVC, where it then hits anti-forgery because there's no request token.

MVC blocking the request due to the missing token makes sense, but the sample app shouldn't be getting that far, as it should be just going to the Minimal API's delete endpoint.

Specific lines from the application logs that are interesting are shown below, with the full logs at the bottom of this issue.

First working request for the HTTP DELETE:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 DELETE https://localhost:5001/api/items/dcd544d4-ff5a-4828-ad35-a6420acec150 - -
<snip>
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/2 DELETE https://localhost:5001/api/items/dcd544d4-ff5a-4828-ad35-a6420acec150 - - - 204 - - 215.2596ms

Second failing request for the HTTP DELETE:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 POST https://localhost:5001/api/items/45ef5916-2b04-4d2a-b060-58fc1105e0c2 - -
trce: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[2]
      All hosts are allowed.
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
      1 candidate(s) found for the request path '/api/items/45ef5916-2b04-4d2a-b060-58fc1105e0c2'
dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
      Request matched endpoint '405 HTTP Method Not Supported'
<snip>
trce: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[2]
      Authorization Filter: Before executing OnAuthorizationAsync on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.AutoValidateAntiforgeryTokenAuthorizationFilter.
info: Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.AutoValidateAntiforgeryTokenAuthorizationFilter[1]
      Antiforgery token validation failed. The required antiforgery header value "RequestVerificationToken" is not present.
      Microsoft.AspNetCore.Antiforgery.AntiforgeryValidationException: The required antiforgery header value "RequestVerificationToken" is not present.
         at Microsoft.AspNetCore.Antiforgery.DefaultAntiforgery.ValidateRequestAsync(HttpContext httpContext)
         at Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.ValidateAntiforgeryTokenAuthorizationFilter.OnAuthorizationAsync(AuthorizationFilterContext context)
trce: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[3]
      Authorization Filter: After executing OnAuthorizationAsync on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.AutoValidateAntiforgeryTokenAuthorizationFilter.
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[3]
      Authorization failed for the request at filter 'Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.AutoValidateAntiforgeryTokenAuthorizationFilter'.
<snip>
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/2 POST https://localhost:5001/api/items/45ef5916-2b04-4d2a-b060-58fc1105e0c2 - - - 400 0 - 46.7893ms

Screenshot showing the two HTTP DELETE calls

Application logs

delete-fails-logs.txt

Expected Behavior

The HTTP DELETE succeeds.

Steps To Reproduce

• Clone martincostello/dotnet-minimal-api-integration-testing@8e09b89
• Configure GitHub auth secrets
• Run the application
• Navigate to https://localhost:5001 in Firefox
• Create two new Todo items
• Delete the two Todo items - the second delete should fail

Exceptions (if any)

No response

.NET Version

7.0.100-preview.1.22110.4

Anything else?

No response

[martincostello]

I'm not sure exactly what is wrong, but debugging this locally this seems to be an issue with HTTP/2 in Kestrel. It seems to be ""remembering"" the HTTP method from somewhere, and then using POST instead of the DELETE from the request, causing the eventual request failure.

If I disable HTTP/2, my tests all pass again.

builder.WebHost.ConfigureKestrel(
    options => options.ConfigureEndpointDefaults(
        defaults => defaults.Protocols = Microsoft.AspNetCore.Server.Kestrel.Core.HttpProtocols.Http1));

See martincostello/dotnet-minimal-api-integration-testing@5952920.

Looking at the commit history, I wonder if it's something related to #38585 and/or #38834?

[martincostello]

I've reached the limit of my understanding of HTTP/2 now, but seems that for some reason the code thinks it needs to use HeaderType.Dynamic for index 3 (which are :method and POST), instead of using the literal value submitted in the request (which are :method and DELETE).

aspnetcore/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Stream.cs

Lines 655 to 659 in 3e6a9ea

	case H2StaticTable.MethodPost:
	HttpRequestHeaders.HeaderMethod = HttpMethods.Post;
	Method = HttpMethod.Post;
	_methodText = HttpMethods.Post;
	return;

[adityamandaleeka]

Thanks for the detailed report @martincostello. We'll take a look.

[Tratcher]

@martincostello in case we have trouble reproducing this, can you capture kestrel connection level logs (after UseHttps decryption)? That should show us the raw HTTP/2 bytes received and enable us to craft a manual repro.
https://docs.microsoft.com/en-us/aspnet/core/fundamentals/servers/kestrel/endpoints?view=aspnetcore-6.0#connection-logging

[adityamandaleeka]

@Tratcher I've got a repro of this.

[martincostello]

Full logs from a repro session attached below. The request that fails starts on line 8801.

dotnet-aspnetcore-issue-40301.txt

Captured with this configuration:

builder.WebHost.ConfigureKestrel((context, serverOptions) =>
{
    serverOptions.Listen(IPAddress.Any, 5000, listenOptions =>
    {
        listenOptions.UseConnectionLogging();
    });
    serverOptions.Listen(IPAddress.Any, 5001, listenOptions =>
    {
        listenOptions.UseHttps();
        listenOptions.UseConnectionLogging();
    });
});

{
  "Logging": {
    "LogLevel": {
      "Default": "Trace",
      "System": "Trace",
      "Microsoft": "Trace",
      "Microsoft.Hosting.Lifetime": "Trace"
    }
  }
}

[adityamandaleeka]

@martincostello Thanks again for filing this issue.

In short, in cases where we are supposed to be using the HPACK static table for just the name of the header and not the value, we are accidentally using both.

For instance, in this particular case, the :method header hits OnHeaderCore with the value DELETE and the static table index for :method POST (https://datatracker.ietf.org/doc/html/rfc7541#appendix-A). This is fine, and we have a codepath that should take care of this:

aspnetcore/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs

Line 1442 in b1df1de

if (staticTableIndex != null)

The bug is that we are incorrectly passing indexOnly: true here:

aspnetcore/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs

Line 1446 in b1df1de

_currentHeadersStream.OnHeader(staticTableIndex.GetValueOrDefault(), indexOnly: true, name, value);

which tells the HttpStream logic to disregard the value and just use the name and value from the static table, which is obviously incorrect.

I will send a PR for this soon. The fix is easy but adding a test is a bit tricky; we'll need to make some changes in our HTTP/2 test code to be able to exercise use of the dynamic table this way.

[martincostello]

@adityamandaleeka Thanks for the explanation of the root cause - I'm not familiar with HPACK so I was lost in the context of what it should or shouldn't be doing with respect to HPACK when I tried debugging it myself 😄