How to capture and respond to Kestrel BadHttpRequestException

[olavaukan]

I recently spent a lot of time troubleshooting a problem that was caused by sending requests with invalid headers. The reason it took so long to troubleshoot was that there was nothing in my logs. I have a fairly elaborate system built up around collecting and processing logs, but in this case I could find nothing. The entire request was missing from all my logs. After a while I was able to ramp up logging to Debug and found this:

{
    "@timestamp": "2020-09-04T14:28:41.8618373+02:00",
    "log.level": "Debug",
    "message": "Connection id \"\"0HM2GPNMRE05A\"\" bad request data: \"\"Malformed request: invalid headers.\"\"",
    "_metadata": {
        "message_template": "Connection id \"{ConnectionId}\" bad request data: \"{message}\"",
        "connection_id": "0HM2GPNMRE05A",
        "message": "Malformed request: invalid headers.",
        "event_id": {
            "id": 17,
            "name": "ConnectionBadRequest"
        },
        "exception_detail": {
            "hresult": -2146232800,
            "message": "Malformed request: invalid headers.",
            "source": "Microsoft.AspNetCore.Server.Kestrel.Core",
            "status_code": 400,
            "type": "Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException"
        },
        "assembly_name": "CustomNamespace.Api",
        "assembly_version": "1.0.0.0"
    },
    "ecs": {
        "version": "1.4.0"
    },
    "error": {
        "message": "Malformed request: invalid headers.",
        "code": "Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException",
        "stack_trace": "Exception 01 ===================================\nType: Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException\nSource: Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException, Microsoft.AspNetCore.Server.Kestrel.Core, Version=3.1.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60\nMessage: Malformed request: invalid headers.\nTrace:    at Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException.Throw(RequestRejectionReason reason)\n   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1Connection.TryParseRequest(ReadResult result, Boolean& endConnection)\n   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication1 application)\n   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync[TContext](IHttpApplication1 application)\nLocation: \nMethod: Void Throw(Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.RequestRejectionReason) (0, 0)\n"
    },
    "event": {
        "severity": 1,
        "timezone": "GMT+01:00",
        "created": "2020-09-04T14:28:41.8618373+02:00"
    },
    "log": {
        "logger": "Microsoft.AspNetCore.Server.Kestrel",
        "original": null
    },
    "process": {
        "thread": {
            "id": 8
        },
        "pid": 1,
        "name": "dotnet",
        "executable": "dotnet",
        "title": ""
    },
    "server": {}
}

I was rather shocked to find that a bad request was logged as Debug. Now there is probably good reasons for this, but I wan't to be able to somehow catch and react to situations like these so I can more easily troubleshoot similar issues in the future. Despite having a global ExceptionFilterAttribute and now attempting to use app.UseExceptionHandler() in my Startup.cs (as discussed here https://www.strathweb.com/2018/07/centralized-exception-handling-and-request-validation-in-asp-net-core/) I can't seem to trigger anything when this error occurs. It seems that bad headers is such a low-level error it's handled deep inside Kestrel somewhere.

So my question then is: can this somehow be captured in some way? If not can I atleast make it log bad requests as Error instead of Debug? Any suggestions will be appreciated...

[Tratcher]

It seems that bad headers is such a low-level error it's handled deep inside Kestrel somewhere.

Correct, if the request is considered malformed the server will refuse it immideately without surfacing it to the application. That's because the server has no confidence that it can properly handle the semantics of the request if it's malformed.

I was rather shocked to find that a bad request was logged as Debug.

It's logged as debug because it's considered an external error that the application can't do anything about. We do something similar for client disconnect errors.

What you can do today to surface these errors is to selectively enable those server logs. You know it's:

• "logger": "Microsoft.AspNetCore.Server.Kestrel"
• "event_id" "id": 17,

@shirhatti can that be done with log filters, or do you need a custom provider? It looks like filters can only get you down to the logger level (Kestrel), not specific event ids?

[olavaukan]

Thanks for the confirmation and help so far. It's more or less as I suspected then. Will try to find a way to selectively surface these logs with a log filter or custom provider as you suggested.

[shirhatti]

@shirhatti can that be done with log filters, or do you need a custom provider?

You'll need a custom provider 😔

[olavaukan]

Just an FYI for others in the same situation.

My workaround (since I'm using Serilog) was logging these events separately to a separate file.

Log.Logger = new LoggerConfiguration()
    .ReadFrom.Configuration(configuration)
    .MinimumLevel.Override("Microsoft.AspNetCore.Server.Kestrel", LogEventLevel.Debug)
    .WriteTo.Logger(lc => lc
        .Filter.ByExcluding(Matching.FromSource("Microsoft.AspNetCore.Server.Kestrel"))
        .WriteTo.Async(a => a
            .File(path: applicationLogFilePath,
                formatter: formatter,
                rollingInterval: RollingInterval.Day,
                rollOnFileSizeLimit: true,
                retainedFileCountLimit: 10)
        )
    )
    .WriteTo.Logger(lc => lc
        .Filter.ByIncludingOnly(Matching.FromSource("Microsoft.AspNetCore.Server.Kestrel"))
        .Filter.ByIncludingOnly(logEvent => logEvent.Exception is BadHttpRequestException)
        .WriteTo.Async(a => a
            .File(path: kestrelExceptionsLogFilePath,
                formatter: formatter,
                rollingInterval: RollingInterval.Day,
                rollOnFileSizeLimit: true,
                retainedFileCountLimit: 10)
        )
    )
    .CreateLogger();