Random 404 errors

[sepehr1014]

On 2.1 RC1, we're getting occasional 404 errors from our API controllers (about 5 in 100). I was wondering if there's a known issue in this release and has a workaround. If not, I would appreciate tips on how to debug this issue and get to the root cause of these 404 errors.

[Tratcher]

No. I suggest you start by enabling logging. Fiddler may also be useful.

[sepehr1014]

Thanks but we already log everything. The request does not reach the action. We also have no filters in the pipeline. Which type of logging do you mean?

…

On Sat, May 19, 2018, 10:01 PM Chris Ross ***@***.***> wrote: No. I suggest you start by enabling logging. Fiddler may also be useful. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#2591 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AK0nhwVI33a-Cp0dOYTk5M-Knx9PWKxpks5t0Fb2gaJpZM4UFqGy> .

[davidfowl]

Turning up the logging verbosity will tell you why the mvc action isn’t getting chosen. Most of our components have their own logging.

[sepehr1014]

I just checked the full logs and spotted something odd. Request.Method is empty! How can that be? Shall I open another issue or track it in the current one?

[davidfowl]

This one is fine if that ends up being the root cause. Do you have the actual log? Can you paste it here?

Also what is your environment setup?

[sepehr1014]

We have a custom exception logger that stores some request properties alongside some other useful data. It would be great if you could tell me which properties to log ... We're using 2.1 RC1 with IIS on Windows Server 2016. The odd thing is that this started to happen about two days ago and the only recent fundamental code change was the use of injected HttpClientFactory instead of a static HttpClient. Can it have anything to do with this issue?

…

On Sat, May 19, 2018, 11:44 PM David Fowler ***@***.***> wrote: This one is fine if that ends up being the root cause. Do you have the actual log? Can you paste it here? Also what is your environment setup? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#2591 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AK0nh4uncHMHTe7UzD4SmvacoTeDPOGKks5t0G8XgaJpZM4UFqGy> .

[sepehr1014]

The culprit was definitely HttpClientFactory. As soon we went back to using a static HttpClient, we don't see this issue anymore.

[davidfowl]

/cc @rynowak @glennc

[shirhatti]

This issue was moved to aspnet/HttpClientFactory#120

[davidfowl]

This might be a real issue in the sever. Here’s another example of the random 404 empty method behavior https://stackoverflow.com/questions/50661923/signalr-core-1-0-intermittently-changes-the-case-of-http-method-for-non-signalr

[davidfowl]

@muratg @halter73 @shirhatti let’s try to figure this out. My gut tells me it’s somethign to do with the perf change that @benaadams made to not stringify the method after parsing.

[benaadams]

Here’s another example of the random 404 empty method behavior

Post in the debug is the enum, rather than string and valid state as that gets converted to POST (there is no POST enum value) - it would be Custom if Kestrel didn't understand it.

HttpProtocol.Reset() sets it the Method to None and the _methodText to null

KestrelHttpServer/src/Kestrel.Core/Internal/Http/HttpProtocol.cs

Lines 328 to 329 in 0aff4a0

	Method = HttpMethod.None;
	_methodText = null;

The one accessed by user code, for the string, is IHttpRequestFeature.Method which returns the string _methodText if set, or uses the Method to look it up - this is when Post enum changes to POST string.

KestrelHttpServer/src/Kestrel.Core/Internal/Http/HttpProtocol.FeatureCollection.cs

Lines 43 to 58 in 0aff4a0

	string IHttpRequestFeature.Method
	{
	get
	{
	if (_methodText != null)
	{
	return _methodText;
	}
	_methodText = HttpUtilities.MethodToString(Method) ?? string.Empty;
	return _methodText;
	}
	set
	{
	_methodText = value;
	}

Note, Empty string (rather than null) is counted as a set value and will override the lookup.

So at a guess either something is setting the IHttpRequestFeature.Method string to empty "" or its being accessed prior to the Method enum being set so the getter sets the string to "" because None has no valid string.

As the value is set via parsing start line; the second would suggest the IHttpRequestFeature.Method is being read after the end of the request (e.g. after Reset()) and before the start of the next request - e.g. the HttpContext is being used after the request has ended.

Ofc, is might also be a bug somewhere in Kestrel :)

[benaadams]

If it is out of request reads that symptom could be resolved by changing the get to

string IHttpRequestFeature.Method
{
    get
    {
        if (_methodText != null)
        {
            return _methodText;
        }

        var methodText = HttpUtilities.MethodToString(Method);
        if (methodText != null)
        {
            _methodText = methodText;
        }
        return methodText ?? string.Empty;
    }

However, whatever is doing the out of bound read will either still get "" as the Method and no headers or will read a mix of one request, an empty uninitialized request, and some of the next request.

So its only treating a symptom - not the more problematic cause.

[benaadams]

So... to help track that down, maybe something more like:

string IHttpRequestFeature.Method
{
    get
    {
        if (_methodText != null)
        {
            return _methodText;
        }

        var methodText = HttpUtilities.MethodToString(Method);
        if (methodText != null)
        {
            _methodText = methodText;
        }
        else if (_requestProcessingStatus != RequestProcessingStatus.AppStarted &&
                _requestProcessingStatus != RequestProcessingStatus.ResponseStarted)
        {
            throw new InvalidOperationException("There is no current request. Method is being checked after a request has finished but a new one has not started.");
        }

        return methodText ?? string.Empty;
    }

[benaadams]

Something like this would probably help track it down
https://github.com/aspnet/KestrelHttpServer/compare/dev...benaadams:throw-invalid-op?expand=1

However, alas I don't have the spare time to fix the 434 Warning(s) and 1620 Error(s) it creates in the tests (as the tests don't set the protocol to the started state)

[davidfowl]

@anurse this might be worth looking at for the patch. If it’s indeed SignalR touching the request at the wrong time

[muratg]

Once thing changed after 2.0: we now reset the HttpContext in 2.1 on connection close now. Could be related.

[muratg]

@sepehr1014 are you accessing HttpContext.Request after connection is closed?

[sepehr1014]

@muratg we're accessing it in an exception logger service. Are you referring to somewhere else in our code? The odd thing is that as soon as we ditched the HttpClientFactory and went back to using a static HttpClient, we're not seeing this issue anymore.

[rclabo]

Thank you to everyone who has been looking into this issue. I'm the one that documented my observations at
https://stackoverflow.com/questions/50661923/signalr-core-1-0-intermittently-changes-the-case-of-http-method-for-non-signalr?noredirect=1#comment88344558_50661923 related to this issue.

So it was with great interest that I have been reading this current thread. When I read Ben's comment that "As the value is set via parsing start line; the second would suggest the IHttpRequestFeature.Method is being read after the end of the request (e.g. after Reset()) and before the start of the next request - e.g. the HttpContext is being used after the request has ended." it occurred to me that the issue I am experiences is my fault. However I believe that the code Ben is proposing that would throw an exception in such situations would be a great help in alerting developers to such an issue.

While I can't explain why I see the issue when I register a signalR hub but don't see the issue when no signalR hub is registered, I can say with certainty (I checked in the debugger) that my code is accessing response.Method at a time that looks to be after the end of one request an before the start of the next. In the debugger I see that the request.ContentType is null and the request.Path is null.

The code in my system that made this mistake is code that runs on a background thread and sometimes logs an error. When the error logger is called it gathers context information which when running in context is available but when called from a background thread is of course not. In the past using the System.Web pipeline if it tried to get the current request when running on a background thread it would get null and know it was on a background thread. But in .Net Core when my logger code tries to get context information the IHttpContextAccessor is returning a context object even though (based on the discussions here) it's not safe to check the values of the object or it's sub-objects. My code was expecting IHttpContextAccessor to return null if called out of process, or in between requests, so it didn't realize that checking the related request.Method would gum up the works for the next request to come in.

What's the safest properties on the Context or Request objects returned by IHttpContextAccessor to check to determine that this Context should not be touched because it's "after the end of the request (e.g. after Reset()) and before the start of the next request."?

[benaadams]

My code was expecting IHttpContextAccessor to return null if called out of process, or in between requests, so it didn't realize that checking the related request.Method would gum up the works for the next request to come in.

It does get set to null; however if you capture the execution context in anyway it being set to null won't propagate to you (due to being an asynclocal); and its very hard not to capture the executioncontext...

What's the safest properties on the Context or Request objects returned by IHttpContextAccessor to check to determine that this Context should not be touched because it's "after the end of the request ...

If another requests comes it it will reinitalize; so you will record the second request's data as the errorred request.

What you would probably want to do is record all the data you want to log when the error happens to an object (so you are still in the request flow; and blocking the request completing). Then use that object rather than the httpcontext or any of its sub properties (request, response etc) in the background thread.

[rclabo]

@benaadams thank you for your response. In the case where my logger code is called from a regular request thread, it works just as you have mentioned, it gathers all the context information while (blocking the request from completing) and then does the actually logging async. This scenario works without issue.

The scenario that I was having issue with is one where I have a background process running which calls my logger due to an exception. The logger then, as before, first gathers context info and then logs it async. The problem encountered is that when the logger code (in this case running out of context because it was called from a background thread) tries to gather the context info, it was expecting IHttpContextAccessor to return null but instead received an object, Then it checked the request.Method to log that info and that gummed up the works for the next request.

So I need some way to check if the object returned from IHttpContextAccessor is in between requests and it's request.Method should not be accessed. In the end I settled on checking to see if it's request.Path == null. Putting this check in my code appears to solve my random 404 problem. If the framework's use of asynclocal causes IHttpContextAccessor to sometimes return a context even when it's in between requests it might make sense for IHttpContextAccessor to check if context.Request.Path == null and return null in such a case rather than return an object that is in between requests. If there is a better test for when the context is in between requests then context.Request.Path == null please let me know.

[benaadams]

I have a background process running which calls my logger due to an exception.

Not sure how you start the background process; but suppress the flow (of asynclocals) beforehand or when calling the logger?

bool restoreFlow = false;
try
{
    if (!ExecutionContext.IsFlowSuppressed())
    {
        ExecutionContext.SuppressFlow();
        restoreFlow = true;
    }

    // Start Background process here
    // Thread.Start/Task.Run/etc

    // Or logging
}
finally
{
    // Restore the current ExecutionContext
    if (restoreFlow)
        ExecutionContext.RestoreFlow();
}

[rclabo]

Ben, I am using ThreadPool.QueueUserWorkItem. You correctly pointed out that doing so will by default flow execution context, and therefore the AsyncLocal used by IHttpContextAccessor flows to my background thread. I agree that this is the source of the random 404 issue I was seeing. I have used code similar to what you suggested to suppress the flow of the execution context and doing so does resolve the issue I was seeing. By doing this, when the background thread uses IHttpContextAccessor to try to access the HttpContext it does properly receive null rather than an object that is in between requests. The bug was clearly mine and not the framework. I'm still getting use to a world with AsyncLocals. I appreciate your help greatly on this. Thank you.

[benaadams]

I am using ThreadPool.QueueUserWorkItem. You correctly pointed out that doing so will by default flow execution context, and therefore the AsyncLocal used by IHttpContextAccessor flows to the new thread in my case.

Ah, in that case you can use ThreadPool.UnsafeQueueUserWorkItem and it will handle the suppression of the ExecutionContext for you

[rclabo]

Sweet. Thank you again!

[davidfowl]

cc @guardrex We need to beef up the doc on IHttpContextAccessor with a gotchas section to capture some best practices when using it within things like background tasks fired off from request threads.

PS: I made change aspnet/HttpAbstractions#1021 based on this discussion to try and mitigate the issue by stashing and clearing some extra information on the async local and request. It's still racy but it should return a null HttpContext more often than not making it easier to catch this sort of problem.

I'm closing this out.