HttpContext.Request.Method is empty

[clement911]

I have an app that runs asp.net core 2.1 on the full .net framework.
Recently, while developing locally, I started getting random errors.
Upon investigation, it is due to an empty HttpContext.Request.Method.

In the log instead of

Microsoft.AspNetCore.Hosting.Internal.WebHost: Information: Request starting HTTP/1.1 GET http://...

We see

Microsoft.AspNetCore.Hosting.Internal.WebHost: Information: Request starting HTTP/1.1 http://...

Notice there is no verb?!

We inspect this request inside a middleware Invoke method
What could cause this property to be empty?
I thought I would try to see the raw request and see the HTTP verb, but I couldn't find a way of seeing the raw request.

If the request really has no verb, I would imagine that asp.net core would throw an exception much earlier?

[davidfowl]

It’s likely you’re accessing the HttpContext between requests. Are you using the IHttpContextAccessor in your application? See aspnet/KestrelHttpServer#2591

[clement911]

We do in a only 2 places but we never write on it. Only read.
Plus, the issue here happens in a middleware so I don't understand how the method could be empty?

[clement911]

We put the following code in an middleware that runs early in the pipeline. It fixes it but we obviously we don't want to keep this:

if (context.Request.Method == "")
{
      context.Request.Method = "GET";
}

[clement911]

Actually regarding your previous comments, I analyzed how we use IHttpContextAccessor.
One place we use it is from a custom logger.
We inspect httpAccessor.HttpContext. If it is non null then we grab some details to augment the log entry with information about the request, such as the url and other stuff.
If it is null, then we assume that a background thread is logging something and therefore do not augment the trace entry.
Is this not a good pattern? We never had issue until recently upgrading to asp.net core 2.1.

[davidfowl]

Doesn’t matter if you write or read, you are accessing it outside of the request it’ll cause this issue. Unfortunately, today the HttpContext is never null so that check won’t work. 2.1 introduced an optimization that made this happen but it’s basislly danger territory. We’ve made a couple of changes in the next version that will hopefully make the HttpContext property null when accessed outside of the request. On top of that in 3.0 the HttpContext will throw an exception when accessed outside of the requests.

For your logggr scenario the best way to go about doing what you want is with a logging scope that copies all of the appropriate properties, that way there’s no chance of using the HttpContext outside of the request scope.

[clement911]

I removed the code using the HttpAccessor and that fixed the issue.
Thank you for your quick help.

But I must say, this is definitely not intuitive, especially coming from previous asp.net stacks.
I really hope you can enhance this to either fail fast or make it just work.

When you say 'outside of the request', do you mean anywhere in background thread or places where the execution context / async local will not flow?

Do you mean that I should create a log scope with BeginScope<TState>(TState state) and copy any property I need from the context into a custom object (TState)?
If so, is a middleware a good place to do that?

It would be great to have this built-in.
I guess I could do that but then how do I pull this state from my Log() method?

Sorry for all the questions but the doc seems very spare in that area...

[clement911]

I can't seem to get it to work.
This is what I have:

public class RequestLogScopeMiddleware
    {
        private readonly RequestDelegate _next;
        private readonly ILogger<RequestLogScopeMiddleware> _logger;

        public RequestLogScopeMiddleware(RequestDelegate next, ILogger<RequestLogScopeMiddleware> logger)
        {
            _next = next;
            _logger = logger;
        }

        public async Task Invoke(HttpContext context)
        {
            _logger.BeginScope("Test");
            await _next(context);
        }
    }

In my logger I'm trying

new LoggerExternalScopeProvider().ForEachScope((s, i) =>
            {
                i++;
            }, 0);

but zero scopes are iterated...

[davidfowl]

But I must say, this is definitely not intuitive, especially coming from previous asp.net stacks.
I really hope you can enhance this to either fail fast or make it just work.

It will going forward, it was an unfortunate consequence on how it was implemented.

When you say 'outside of the request', do you mean anywhere in background thread or places where the execution context / async local will not flow?

What I really mean is using an HttpContext reference that has been disposed because the end of the request already took place. Because it's implemented as a simple async local, you basically get a handle on the previous request depending on how it was captured. This should have been fixed with aspnet/HttpAbstractions@0f4f195 (which tries to return null when the accessing IHttpContextAccessor.HttpContext at the wrong time).

Do you mean that I should create a log scope with BeginScope(TState state) and copy any property I need from the context into a custom object (TState)?
If so, is a middleware a good place to do that?

Yes and Yes.

It would be great to have this built-in.

There's a default logging scope but it only copies a few properties https://github.com/aspnet/Hosting/blob/5a3c6645667ec24e09d6200fb1e949f2a2417b9a/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs#L95.

I guess I could do that but then how do I pull this state from my Log() method?

That's also correct.

Sorry for all the questions but the doc seems very spare in that area...

Yes, we should beef up the docs here @pakrym @guardrex.

I can't seem to get it to work.

I'll try to get your a sample. Are you implementing a custom LoggerProvider? What exactly are you doing?

[clement911]

What I really mean is using an HttpContext reference that has been disposed because the end of the request already took place. Because it's implemented as a simple async local, you basically get a handle on the previous request depending on how it was captured.

Still I'm confused about how the context injected in a middleware's async Task Invoke(HttpContext context) could be from a previous request or in a invalid state since middlewares are running within the scope of a request.

I'll try to get your a sample. Are you implementing a custom LoggerProvider? What exactly are you doing?

That would be great.
From my middleware's Invoke() I'm calling logger.BeginScope(state). My understanding is that middleware are singletons, so I guess the injected logger is also a singleton. I'm not sure if this is problematic.

However, how do I retrieved this scope / state from my ILogger implementation?
I saw that the ConsoleLogger was using new LoggerExternalScopeProvider() but I couldn't get it working. No scopes are iterated when calling ForEachScope

[davidfowl]

Still I'm confused about how the context injected in a middleware's async Task Invoke(HttpContext context) could be from a previous request or in a invalid state since middlewares are running within the scope of a request.

It's not the context inject into your middleware, it's the HttpContext property accessed from IHttpContextAccessor that's the problem. You're basically grabbing it out of thin air and expecting it to be null or the "current" HttpContext for the async flow. At the moment, you can end up in a place where the request is over and that property doesn't return null as a result.

That would be great.
From my middleware's Invoke() I'm calling logger.BeginScope(state). My understanding is that middleware are singletons, so I guess the injected logger is also a singleton. I'm not sure if this is problematic.

Sure you can just BeginScope to pass an object that has a set of name value pairs like I showed before that will be passed to all of the logger providers.

However, how do I retrieved this scope / state from my ILogger implementation?
I saw that the ConsoleLogger was using new LoggerExternalScopeProvider() but I couldn't get it working. No scopes are iterated when calling ForEachScope

You're missing more of the code, implementing an ILoggerProvider is more involved. May I ask why you are implementing a custom provider instead of just using something like Serilog?

[clement911]

It's not the context inject into your middleware, it's the HttpContext property accessed from IHttpContextAccessor that's the problem. You're basically grabbing it out of thin air and expecting it to be null or the "current" HttpContext for the async flow. At the moment, you can end up in a place where the request is over and that property doesn't return null as a result.

Maybe I wasn't clear earlier.
I can understand that, when grabbing the context from the IHttpContextAccessor, the context may be invalid.
However, the original reason I raised the issue is because the instance injected into my middleware was invalid (HttpContext.Request.Method was empty).
The mere fact of removing the code that used the IHttpContextAccessor in a completely different part of the code (our custom logger) seems to have prevented the context injected into the middleware to be invalid.
That doesn't make sense at all to me.
Why should a piece of code completely unrelated, albeit buggy, cause the injected context in the middleware to be in a different state?
If this buggy code was in a third party library, could this crash my own middlewares too?!
This is strange to me. Maybe I'm missing something...

You're missing more of the code, implementing an ILoggerProvider is more involved. May I ask why you are implementing a custom provider instead of just using something like Serilog?

In general I like to keep the number of package dependencies and moving parts to a minimum to keep things simple and understand what is going on.
Why should I need a separate package to implement a simple logging sink?
The ILoggerProvider/ILogger interfaces are simple but the one member I ignored so far is the BeginScope() method.
This seems harder than it should be and I'm thinking of just using CallContext.LogicalSetData to store my http context info. This API is very straightforward and served me well before
Is there any magic or reason in asp.net core that this might be a bad idea?

I'll post below a simplified version of my Logger/LoggerProvider

public class NcLoggerProvider : ILoggerProvider
    {
        private readonly IServiceProvider _serviceProvider;

        public NcLoggerProvider(IServiceProvider serviceProvider)
        {
            _serviceProvider = serviceProvider;
        }

        public ILogger CreateLogger(string categoryName)
        {
            var logger = _serviceProvider.GetRequiredService<NcLogger>();
            //transient logger allows each logger to have its own category
            logger.CategoryName = categoryName;
            return logger;
        }

        public void Dispose()
        {
        }
    }


public class NcLogger : ILogger
    {
        public string CategoryName { get; set; }
        
        public IDisposable BeginScope<TState>(TState state)
        {
            return Disposable.Empty;
        }

        public bool IsEnabled(LogLevel logLevel)
        {
            return true;
        }

        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
        {
            string message = formatter(state, exception);
            //commenting out the following line fixed my original issue
            string httpInfo = null;//this.GetHttpInfo(_httpAccessor.HttpContext);
            PersistLogEntry(message, httpInfo);
        }

        private void PersistLogEntry(string message, string httpInfo)
        {
            //omitted
        }
    }

[davidfowl]

This is strange to me. Maybe I'm missing something...

Maybe this will help https://stackoverflow.com/a/51063132/45091.

In general I like to keep the number of package dependencies and moving parts to a minimum to keep things simple and understand what is going on.

That's fair, but Serilog is good, really really good and well implemented by somebody that understand the complexities in logging and has very useful sinks and provider implementations.

The ILoggerProvider/ILogger interfaces are simple but the one member I ignored so far is the BeginScope() method.
This seems harder than it should be and I'm thinking of just using CallContext.LogicalSetData to store my http context info. This API is very straightforward and served me well before
Is there any magic or reason in asp.net core that this might be a bad idea?

There are better ways to do this now. In particular you can use an AsyncLocal to store the state. Also, this is built into the logging system now so you don't need to do this yourself.

Since you insist on writing a custom logger provider (which I recommend against), here's an example of a bare minimum implementation:

PS: You're supposed to fill the "Do the logging here" section to push this data somewhere.

using System;
using System.Collections.Generic;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.DependencyInjection.Extensions;
using Microsoft.Extensions.Options;

namespace Microsoft.Extensions.Logging
{
    public class SampleLoggerProvider : ILoggerProvider, ISupportExternalScope
    {
        private IExternalScopeProvider _scopeProvider;
        private readonly SampleLoggerProviderOptions _options;

        public SampleLoggerProvider(IOptions<SampleLoggerProviderOptions> options)
        {
            _options = options.Value;
        }

        public ILogger CreateLogger(string categoryName)
        {
            return new SampleLogger(categoryName, _scopeProvider, _options);
        }

        public void Dispose()
        {
        }

        public void SetScopeProvider(IExternalScopeProvider scopeProvider)
        {
            _scopeProvider = scopeProvider;
        }
    }

    internal class SampleLogger : ILogger
    {
        private readonly string _categoryName;
        private readonly IExternalScopeProvider _scopeProvider;
        private readonly SampleLoggerProviderOptions _options;

        public SampleLogger(string categoryName, IExternalScopeProvider scopeProvider, SampleLoggerProviderOptions options)
        {
            _categoryName = categoryName;
            _scopeProvider = scopeProvider;
            _options = options;
        }

        public IDisposable BeginScope<TState>(TState state)
        {
            return _scopeProvider.Push(state);
        }

        public bool IsEnabled(LogLevel logLevel)
        {
            return true;
        }

        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
        {
            var properties = new Dictionary<string, object>
            {
                ["CategoryName"] = _categoryName,
                ["Message"] = formatter(state, exception),
                ["Level"] = logLevel
            };

            if (exception != null)
            {
                properties["Exception"] = exception.ToString();
            }

            if (eventId.Id != 0)
            {
                properties["EventId"] = eventId.Id.ToString();
            }

            if (!string.IsNullOrEmpty(eventId.Name))
            {
                properties["EventName"] = eventId.Name;
            }

            if (state is IEnumerable<KeyValuePair<string, object>> stateDictionary)
            {
                foreach (KeyValuePair<string, object> item in stateDictionary)
                {
                    properties[item.Key] = item.Value;
                }
            }

            // Add scopes
            _scopeProvider.ForEachScope((value, loggingProps) =>
            {
                if (value is IEnumerable<KeyValuePair<string, object>> props)
                {
                    foreach (var pair in props)
                    {
                        loggingProps[pair.Key] = pair.Value;
                    }
                }
            },
            properties);

            // Do the logging here
        }
    }

    public static class MyLoggerProviderExtensions
    {
        public static ILoggingBuilder AddSampleLoggerProvider(this ILoggingBuilder builder, Action<SampleLoggerProviderOptions> configure)
        {
            builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton<ILoggerProvider, SampleLoggerProvider>());
            builder.Services.Configure(configure);

            return builder;
        }
    }

    public class SampleLoggerProviderOptions
    {
        // Put options here
    }
}

[clement911]

Maybe this will help https://stackoverflow.com/a/51063132/45091.

Sorry but it doesn't. This explains why the context is in an invalid state in a background thread, but not in the Invoke method of a Middleware, since at this point there is a request in progress.
I still don't get it.

Thank you so much for this sample! I will give it a try

[clement911]

Your sample works well, thank you.

IMHO the API is very weird though.
It would be a lot more natural if instead of ForEachScope it exposed a IEnumerable<object>.

As I mentioned I still don't understand the invalid context in the middleware's Invoke, but feel free to close this issue as you see fit.

[clement911]

I guess it might be this way for perf reason: aspnet/Logging#723

[davidfowl]

Sorry but it doesn't. This explains why the context is in an invalid state in a background thread, but not in the Invokemethod of a Middleware, since at this point there is a request in progress.
I still don't get it.

It's invalid in the next request because you accessed the http context between the previous request and the next request in your logger provider implementation. Like I said in all versions <= 2.1, the IHttpContextAccessor.HttpContext may not return null in some cases, so you may end up with an HttpContext thats nulled out internally (which you are likely reading and logging). This in turn corrupts the next request.

Here's the relevant excerpt from the stack overflow post if you didn't get through it:

Starting in .Net Core 2.0 the HttpContext, and it's child objects like request, gets reset after the connection for a request closes. So the HttpContext object (and it's request object) the logger code was getting when running on a background thread was an object that had been reset. It's request.Path for example was null.

It turns out that a request in this state does not expects it's request.Method property to be accessed. And doing so gums up the works for the next request that comes in. Ultimately this is the source of why the next request that came in ended up returning a 404 error.

aspnet/KestrelHttpServer#2591 (comment)

I guess it might be this way for perf reason: aspnet/Logging#723

Yes, performance is a concern.

Glad you got it working scopes are the way to go here.

[poke]

However, the original reason I raised the issue is because the instance injected into my middleware was invalid

Note that you are injecting IHttpContextAccessor—the accessor—not the context itself. The accessor will always be valid and will get properly injected. But accessing the context using the accessor is not a safe operation outside of HTTP requests. And before that change that David linked, there were simply no safeguards that prevented you from accessing it.

[clement911]

It's invalid in the next request because you accessed the http context between the previous request and the next request in your logger provider implementation.

Got it. Looking forward to the fix in a future release. I'm pretty sure it will save other people wondering what's happening.

@poke:

Note that you are injecting IHttpContextAccessor—the accessor—not the context itself. The accessor will always be valid and will get properly injected. But accessing the context using the accessor is not a safe operation outside of HTTP requests. And before that change that David linked, there were simply no safeguards that prevented you from accessing it.

No actually it is the context itself that is being injected in the middleware:
public async Task Invoke(HttpContext context)