aspnet / AspNetKatana

Microsoft's OWIN implementation, the Katana project
Apache License 2.0
968 stars 334 forks source link

Server cannot append header after HTTP headers have been sent #74

Open ArtemAvramenko opened 7 years ago

ArtemAvramenko commented 7 years ago

Occasionally CookieAuthenticationHandler throws HttpException:

    Exception type: HttpException 
    Exception message: Server cannot append header after HTTP headers have been sent.
   at System.Web.HttpHeaderCollection.SetHeader(String name, String value, Boolean replace)
   at Microsoft.Owin.Host.SystemWeb.CallHeaders.AspNetResponseHeaders.Set(String key, String[] values)
   at Microsoft.Owin.Infrastructure.ChunkingCookieManager.AppendResponseCookie(IOwinContext context, String key, String value, CookieOptions options)
   at Microsoft.Owin.Security.Cookies.CookieAuthenticationHandler.<ApplyResponseGrantAsync>d__f.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Owin.Security.Infrastructure.AuthenticationHandler.<ApplyResponseCoreAsync>d__b.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Owin.Security.Infrastructure.AuthenticationHandler.<ApplyResponseAsync>d__8.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Owin.Security.Infrastructure.AuthenticationHandler.<TeardownAsync>d__5.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Owin.Security.Infrastructure.AuthenticationMiddleware`1.<Invoke>d__0.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage.<RunApp>d__5.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContext.<DoFinalWork>d__2.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.StageAsyncResult.End(IAsyncResult ar)
   at System.Web.HttpApplication.AsyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Version of Microsoft.Owin.Security: 3.0.1

Is this problem fixed in the latest version?

Tratcher commented 7 years ago

Looks like http://katanaproject.codeplex.com/workitem/472

phaselden commented 7 years ago

Possibly related:

FrediPouce commented 7 years ago

Hi,

We have excactly the same issue. Anyone could provide a workaround to avoid the issue ?

Two ways to reproduce the problem:

Thanks for your help.

Microsoft.Owin.Security: 3.0.1 and tested also with the version 3.1.0 (same issue)

dmytro-gokun commented 7 years ago

We also have the same issue with Microsoft.Owin.Security 3.1.0

chrisjsmith commented 7 years ago

Same issue here.

xantari commented 6 years ago

Still seeing this with .NET 4.6.2. Some indications that this occurs when the sliding expiration cookie gets renewed.

Possible rleated issue, with OwinServerCompressionHandler: https://github.com/azzlack/Microsoft.AspNet.WebApi.MessageHandlers.Compression/issues/13

sanjogs commented 6 years ago

Same issue here with WebForms. Any chance this is getting addressed in next update?

Tratcher commented 6 years ago

Unfortunately the deprecation of Codeplex has broken all of our links...

The only repro I have for this right now is when you request a root page like "/" and internally it gets routed to a default file like "/default.aspx". IIS uses a feature called child requests to execute "/default.aspx" so it looks like the request is executed twice. The child request "/default.aspx" works fine and the client gets that result. After that duplicate logic runs on the origiinal "/" request. It doesn't know the response already started so CookieAuth tries to refresh it's cookie and throws. The client gets the response from the child request, so the only impact of the failure is an annoying log.

Does this match anyone's experience?

sanjogs commented 6 years ago

@Tratcher I think that's exactly what we are experiencing, the errors we are getting is at the root '/'. Problem is just the annoying log, client does not experience any issues.

xantari commented 6 years ago

Any news on this one?

Tratcher commented 6 years ago

@xantari does https://github.com/aspnet/AspNetKatana/issues/74#issuecomment-362428094 match your experience?

If this only manifests in a log and does not impact clients then it's a low priority to address.

xantari commented 6 years ago

@Tratcher We get an email on all errors, receive several hundred of these a day. Also our SIEM (Security Information and Event Management) systems are also receiving those logs since they harvest from the event log and consuming unnecessary space our our SIEMS and causing unnecessary log reviews by our security administrators. Additionally, they are also replicated to our tripwire log server as well, and in the windows event logs. All of which sifting through is causing us pain, when we want to see the real errors in our applications. It is a LOT of noise, that causes us a lot of pain.

xantari commented 6 years ago

We have spent countless hours so far trying to figure out why it occurs, but have come up empty. We currently have a contract in process to hire an external expert to see if they can fix the issue. Spending thousands on that contract.

bbarrick commented 6 years ago

We are getting this error now after upgrading to 4.0.

kemmis commented 6 years ago

would like to see this fixed. lots and lots of noise in our log.

Workshop2 commented 6 years ago

We get loads of these in our logs - are there plans to fix it?

Tratcher commented 6 years ago

See above. https://github.com/aspnet/AspNetKatana/issues/74#issuecomment-370000081

irfan-yusanif commented 5 years ago

When a hit my website's page after about 20 minutes of inactivity, I get this warning in event logs "Server cannot append header after HTTP headers have been sent", and the user is logged out.

I can't see any other reason to logout the user, i think this is expiring the cookies?

Tratcher commented 5 years ago

@watoo sounds like a sliding refresh of the cookie.

jeremeguenther commented 5 years ago

Has anyone found a fix for this issue? I am not aware of any Owin upgrades I have done recently, I am using version 3.1.0.0, which has been running fine for quite awhile. Now all of a sudden my logs are getting filled with this odd HTTP headers error.

It's always thrown at the application level, two identical errors are always thrown one after the other, and it is always at the root of the site, and always by a logged in user.

So it sounds very much like it might be triggered by some sliding cookie issue as mentioned prior in this thread.

This is the stack trace:

Message: Server cannot append header after HTTP headers have been sent. StackTrace: at System.Web.HttpHeaderCollection.SetHeader(String name, String value, Boolean replace) at Microsoft.Owin.Host.SystemWeb.CallHeaders.AspNetResponseHeaders.Set(String key, String[] values) at Microsoft.Owin.Infrastructure.ChunkingCookieManager.AppendResponseCookie(IOwinContext context, String key, String value, CookieOptions options) at Microsoft.Owin.Security.Cookies.CookieAuthenticationHandler.df.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Owin.Security.Infrastructure.AuthenticationHandler.db.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Owin.Security.Infrastructure.AuthenticationHandler.d8.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Owin.Security.Infrastructure.AuthenticationHandler.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Owin.Security.Infrastructure.AuthenticationMiddleware`1.d0.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContext.d__2.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.StageAsyncResult.End(IAsyncResult ar) at System.Web.HttpApplication.AsyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step) at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Tratcher commented 5 years ago

See https://github.com/aspnet/AspNetKatana/issues/74#issuecomment-370000081

jeremeguenther commented 5 years ago

I read the thread already, that is why I posted here. We all know the issue exists, which is what comment 74 confirms. What I asked is if there was a work around to fix it until the code base has been fixed.

Like others here this is filling up my error logs and has wasted a lot man hours reviewing logs for what seems to be a known bug. But it is not a consistent bug for everyone, which means there is probably a work around that could be implemented.

At the moment it sounds like this thread is saying Microsoft views this issue as such a low priority that not only is it not going to fix it any time soon, it isn't going to look into a work around either. I am hoping some other brilliant person has found that work around.

phaselden commented 5 years ago

It might not be ideal, but until this is addressed we prevent these getting into our logs we capture and ignore them in the application-level error handler. e.g.:

Exception exc = Server.GetLastError();
if (exc.GetType() == typeof(HttpException) && exc.Message.Contains("Server cannot append header after HTTP headers have been sent"))
{
    Server.ClearError();
}
jeremeguenther commented 5 years ago

That is similar to the approach I am taking, I am setting a unique flag on this type of error so I can ignore it. It is not a good solution though because that Message could very well be a valid error message for the site if I were to mess up and try and set headers somewhere in code after the response has already been sent.

rcorfman commented 5 years ago

So is there a way to work with this? Yes I've read #74 comment and that does seem to match my experience. But for my app, this does affect clients as certain claims that were just created are no longer in the identity. The current work around is for users to log off and sign back in, or to just have a coffee and try again later. But that seems to be temporary since this may occur again a short time later. I suppose I could move the claims into application user but that seems counter to the whole claims concept.

Tratcher commented 5 years ago

@rcorfman in the repro above (https://github.com/aspnet/AspNetKatana/issues/74#issuecomment-362428094) the client gets the response from /default.aspx, but not the from the duplicate request to /. Are you producing different results on the first and second request? Or do you have a different repro?

rcorfman commented 5 years ago

@Tratcher thanks for the quick reply. I catch the exception in Global.Application_Error and at that point the raw URL seems to always be "/". Beyond that, I don't know. I haven't been able to reproduce this, I just see the results in my web app's log files. When a user signs in or gets authenticated through a cookie, the app retrieves some user information from a third party web service which is then saved as claims. Those claims are lost when this occurs. I recently converted my webforms app from membership to identity.

Tratcher commented 5 years ago

When a user signs in or gets authenticated through a cookie, the app retrieves some user information from a third party web service which is then saved as claims.

In this scenario that should be happening twice, and the user should be getting the results from the first one. I'd only expect a user facing problem if the claims were different from the second request.

rcorfman commented 5 years ago

@Tratcher It only happens once though that's probably because I never moved it out of Global.Session_Start. I glanced at moving it to ApplicationUser.GenerateUserIdentity, but I don't yet understand the flow for when/how it is called.

jeremeguenther commented 5 years ago

I have gotten to the point where I can consistently recreate this issue, this is what I have found.

This occurs when a user selects the "remember me" checkbox which causes a persistent cookie to be written to their machine. If they then do not log out of the site for over half of the timespan of the owin cookie expiration window set in Startup ( which is when Owin checks for and attempts to refresh the cookie), and then if they try to go to the root of the site on their first connection to the app after this period this error is triggered.

This error is appears to be a bug in Owin during the cookie refresh process when the site is going to be redirected. This bug is triggered in conjunction with the authentication redirection module in .net.

So basically, the redirect module must run, set and send the headers to redirect user, then the Owin module attempts to refresh the users cookie and set additional headers without first checking if they have already been set.

Tratcher commented 5 years ago

@jeremeguenther why is the app being redirected? You said the cookie is still valid but is being updated due to the sliding expiration. It's also not clear how the persistent cookie would effect this, the sliding cookie expiration time is embedded in the cookie value.

jeremeguenther commented 5 years ago

@Tratcher you are right, it is happening where the redirect to /login.aspx would normally occur if the user were logged out. But since the user simply needs their cookie updated an error is thrown instead.

You are also correct in that it is not specific to the persistent cookie, I was able to recreate it both with and without IsPersistent set to true in the AuthenticationProperties.

By setting my AuthenticationProperties.ExpiresUtc to 10 seconds in the future, my validateInterval to 10 seconds, and my ExpireTimeSpan to 1 minute, I am able to re-create this issue at will by simply logging in, waiting about 5 seconds, then navigating to the root of the web forms site. If I wait 10 seconds then I am logged out.

Going back and re-viewing the repro you have in your comment again, this does seem to be the same thing. Unfortunately, that doesn't help those who need a fix, this error can also be thrown by other code, so unless we inspect the stack trace on every error, we would never know if it is the CookieAuth bug or one we need to worry about.

jeremeguenther commented 5 years ago

It looks like Owin has two bugs in it:

ChunkingCookieManager.cs method AppendResponseCookie has the error this thread was started for where it tries to modify headers without checking to see if it can first. You can get around this error by creating a custom CookieManager : ICookieManager and wrap the ChunkingCookieManager.

But then you come up against the second bug CookieAuthenticationHandler.cs method ApplyResponseGrantAsync about line 275 sets headers without first checking to see if they were already sent.

I have not yet figured out how to wrap/replace the CookieAuthenticationHandler, but at some point this gets rather silly as we could just end up replacing most of owin depending on how many of these bugs exist.

Tratcher commented 5 years ago

@jeremeguenther in every case that we've seen this bug, the request is actually a duplicate child request and the response generated (or error) does not surface to the client. That's why the headers are in an unexpected state.

Does anything in your repro indicate otherwise?

jeremeguenther commented 5 years ago

Yes, I agree with that statement, this is a duplicate request that the client never sees. And according to the IIS documentation this parent/child request is the expected design.

What I am failing to understand is why Microsoft has intentionally designed software that throws generic, uncaught exceptions in standard code. As near as I can tell from my testing this must be affecting all web servers that use owin cookie authentication, it does not seem to be just an "every case" kind of thing; if it were there would be a work around, most people just are not complaining about it. Even catching and throwing a custom exception seems like a better choice.

If this is just an "every case" kind of bug, then I would love to hear what configuration setting triggers it that can be changed to work around it.

So far the response we have gotten seems to be that Microsoft knows this is blowing up web servers, crashing code, filling up logs, and causing additional exception handling overhead on the thread it is running on. But, because it is not visible to the end user, they do not care. I do not understand that attitude, and sure wish I had waited to start using Owin until it was more stable.

jeremeguenther commented 5 years ago

For those in this thread still looking for a solution. I took @phaselden 's method of handling things and took it a bit further by wrapping the exception to uniquely identify this specific known exception better. I detailed my findings and the work around I ended up going with here.

Tratcher commented 5 years ago

@jeremeguenther nice investigation and writeup. The fundamental issue here is not the exception but the double request execution. If it were possible to detect the duplicate request in a middleware at the start of the pipeline you could short circuit the entire pipeline and the rest of the middleware wouldn't have to worry about it.

In my testing the child request is the more specific one (/default.aspx), it starts second, finishes first, and that's the response the client gets. I don't see a way to detect that a request is a parent of a child, nor any way to preserve state between the two, it doesn't look like anything is shared between them.

jeremeguenther commented 5 years ago

It looks as though headers get shared. You could set a header and check for its existence/value in the parent code, although I admit that feels like a pretty poor solution as it is more data being sent to the client. But since the middleware itself is generating cookies in this case, maybe there is one of those you could check for.

Here are some additional things that could be tried:

Tratcher commented 5 years ago

Clever, I'd tried response headers, server variables, and Items but those aren't shared.

This works fine to prevent the pipeline from running on parent requests.

    public partial class Startup {
        public void Configuration(IAppBuilder app) {
            app.MapWhen(IsChildRequest, ConfigureAuth);
        }

        private bool IsChildRequest(IOwinContext context)
        {
            var childRequestHeader = context.Request.Headers["x-parent-breadcrumb"];
            if (childRequestHeader != null)
            {
                return true;
            }

            context.Request.Headers["x-parent-breadcrumb"] = "1"; // arbitrary value
            return false;
        }
    }

Problem: It works too well. Some requests don't have child requests and we need to allow the pipeline to run for those.

Worst case we could insert a marker like this to prevent ApplyResponseAsync from running twice. at Microsoft.Owin.Security.Infrastructure.AuthenticationHandler<ApplyResponseAsync>d__8.MoveNext() https://github.com/aspnet/AspNetKatana/blob/0f6dc4bf2722fb08759da3eacaf38f2a098771bd/src/Microsoft.Owin.Security/Infrastructure/AuthenticationHandler.cs#L176

jeremeguenther commented 5 years ago

What if you added an additional constraint on there. Request.Uri.AbsolutePath == "/"

So far this has only been an issue at root correct? And root requests will always have the parent/child requests unless it is not in integrated mode. A flag, or configuration could be provided to allow developers to specify if they are not running in integrated mode.

Another option, if the request headers are shared rather than copied into the child, would be to do the check later on in the pipeline. Not quite as clean, but then the child request would run first and you would know it existed, and the parent could detect it.

Tratcher commented 5 years ago

What if you added an additional constraint on there. Request.Uri.AbsolutePath == "/"

That's too fragile for framework code. Any call to TransferRequest would trigger the same issue. You're welcome to apply it yourself.

What do you mean by later in the pipeline? At what point would you expect that check to work?

jeremeguenther commented 5 years ago

The - later in the pipeline - option would only work if the request headers are shared between the two requests. In other words, if the child request modifications can be seen by the parent request. In which case the header could be set in the Configuration method, but the parent would then have to check the request headers at some point after control was returned back to the parent.

That would also require a value to be set somewhere like the response headers that are not shared so the parent could determine if it were the one to set the request header.

Your apply marker idea is probably better than this option, if this option would even work.

warrenkc commented 4 years ago

Has this been fixed?

Tratcher commented 4 years ago

@warrenkc no. Do you have any indication it's causing a product issue? All reports so far have only been of log noise.

warrenkc commented 4 years ago

I really don't know if it causes any issue. But for now I will add this to my Global.asax.cs file: Exception lastError = Server.GetLastError(); if (lastError.GetType() == typeof(HttpException) && lastError.Message.Contains("Server cannot append header after HTTP headers have been sent")) { Server.ClearError(); return; }

Tratcher commented 4 years ago

That might cut down on the noise, but it shouldn't have any functional benefits.

warrenkc commented 4 years ago

So really this error shouldn't actually affect anything in a negative way other than creating error log entries?

Tratcher commented 4 years ago

That's been the case for all reports so far. Let us know if you see otherwise.

Bykiev commented 4 years ago

Is any chance it will be ever fixed? I'm using this library: https://github.com/azzlack/Microsoft.AspNet.WebApi.MessageHandlers.Compression and because of this bug I need to install additional package OwinServerCompressionHandler to workaround the issue

dbarrett84 commented 4 years ago

That's been the case for all reports so far. Let us know if you see otherwise.

Hi Tratcher, we are seeing an issue for the end user just recently.

A particular customer has setup their session timeout to be 16 minutes. We have some API endpoints that could take up to 5 seconds to complete and return a response.

Anytime a user makes a request to one of these API endpoints on the 8 minute mark, they get no response from the server. From dev tools it will look like a failed request, but the request was successful just the endpoint could not return the response because of this issue. image