Wednesday, June 19, 2019

Microsoft Owin Http append header bug

I've been dealing with an exception for most of this year that has really been annoying.

This bug is specific to .net Owin code, possibly even the CookieAuthentication method when running under IIS in an integrated pipeline.  While this sounds very specific, I believe it is actually one of the more common setups for .net and IIS.

After the first couple of months I looked into it and found that others were having the same issue.  Unfortunately, Microsoft already knew about it and responded that the fix for it was such a low priority that they were not going to bother with it any time soon.

After many months of dealing with this annoying bug I finally found time to spend several days digging into Microsoft's code to see what was causing it.

As the Microsoft guy had indicated, it was the parent/child request scenario in IIS that was triggering the issue.  When I first read his response I did not really understand what he meant by it, or how it was triggering the errors.

Recreating the error

I needed to re-create it for myself so I could understand what was going on.  I started by setting my sign-in cookie to expire after 10 seconds on my login page.

            var authenticationManager = HttpContext.Current.GetOwinContext().Authentication;
            authenticationManager.SignIn(new AuthenticationProperties()
            {
                IsPersistent = chkRemember.Checked, // Tells OWIN whether or not to create a persistent cookie instead of just a session cookie
                IssuedUtc = DateTime.UtcNow,
                ExpiresUtc = DateTime.UtcNow.AddSeconds(10)
            }, userIdentity);

Next, in my Startup.cs I set my ExpireTimeSpan to 1 minute, and my validateInterval to 10 seconds.  I'm not sure that ExpireTimeSpan actually does anything, it feels like it gets over-ridden by the ExpiresUtc from the SignIn code.

            var cookieExpiration = TimeSpan.FromMinutes(1);
            var checkPeriod = TimeSpan.FromSeconds(10);

            app.UseCookieAuthentication(new CookieAuthenticationOptions
            {
                ...
                Provider = new CookieAuthenticationProvider
                {
                    OnValidateIdentity = SecurityStampValidator.OnValidateIdentity(
                        validateInterval: checkPeriod,
                        regenerateIdentity: (manager, user) => manager.CreateIdentityAsync(user, DefaultAuthenticationTypes.ApplicationCookie)
                        ),
                },
                ExpireTimeSpan = cookieExpiration,
                SlidingExpiration = true,
            });

Once I had these very short times in place I started up the site.  By first logging in and then, after 5 seconds had passed and before the 10 second mark, navigating to the root of the site ( "/" ) I was able to consistently generate the error.  Every 5 seconds or so if I went to the root I would throw that error.  As expected, the user never actually sees the error, it just gets thrown in back end code, so any logging you have setup should catch it.

Cause

If you did not read any of the articles linked to above, this error is caused by two things.  First, IIS in integrated mode will execute the .net code twice when the site root is requested.  First it starts what is called the "parent" call, but immediately sees that the request is for root, which does not exist, so it starts a "child" call to whatever the default document is.  This child call executes correctly and is prepped for return to the client.  When the child call is finished, the parent call resumes executing, only now the Response has already been created and prepared for the client, and this is where the Owin bugs come into play.

Because the Owin code does not check before attempting to set header information in the default ChunkingCookieManager, it blows up during this parent call as Owin is trying to write out cookie information to the header.  This bug actually exists at least twice in Owin, so if you fix the first one, then the second one still blows up with the same error just in a different place.

The bad news is that there is no good or easy way to deal with this error.  The good news is that there is a way of wrapping the first error so that your error handler can uniquely identify and handle it with minimal effort.

Solution 1:

In Global.asax.cs in the Application_Error method, where you are likely trapping the errors, you can inspect the error description as well as its stack trace and make a decision on how to handle it that way.

        protected void Application_Error(object sender, EventArgs e)
            Exception parent_ex = Server.GetLastError();
            Exception ex = parent_ex.GetBaseException();
            if(ex.Message.StartsWith("Server cannot append header after HTTP headers have been sent.") && ex.StackTrace.Contains("Microsoft.Owin.Infrastructure.ChunkingCookieManager.AppendResponseCookie"))  then do something

Solution 2:

While neither of these solutions is great, and solution 1 is easier, it also feels messier.  The second solution is to wrap the CookieManager and catch and wrap the exception there.  This feels cleaner because it is much closer to the source, unfortunately you cannot handle the error there or the next error will just crop up.

replace the default CookieManager with your custom wrapper:

            app.UseCookieAuthentication(new CookieAuthenticationOptions
            {
                ...
                CookieManager = new ChunkingCookieManagerHeaderSentCheck(),
                ...


then, for the most part, just wrap the default ChunkingCookieManager.  However, in the problem method insert a try/catch that provides a bit more detail.  You still have to look for this detail in Global.asax.cs, but it is better than trying to comb through a stack trace.  You could also use a custom exception here with extra fields that could help you in identifying this specific exception.

    public class ChunkingCookieManagerHeaderSentCheck : ICookieManager
    {
        private readonly ChunkingCookieManager _chunkingCookieManager;

        public ChunkingCookieManagerHeaderSentCheck()
        {
            _chunkingCookieManager = new ChunkingCookieManager();
        }

        public string GetRequestCookie(IOwinContext context, string key)
        {
            return _chunkingCookieManager.GetRequestCookie(context, key);
        }

        public void AppendResponseCookie(IOwinContext context, string key, string value, CookieOptions options)
        {
            /*
             * Microsof's Chunking Cookie Manager has a bug in it where it does not check to see
             * if headers have already been sent before it attempts to set more.
             * The exception cannot be dealt with here because the same bug exists in
             * CookieAuthenticationHandler.ApplyResponseGrantAsync.
             * Since it is harder to catch that one, it is best to just let this one be thrown,
             * but add some explanation to it so error handling can single it out in Global.asax.cs
             * and deal with it appropriately.
             */
            try
            {
                _chunkingCookieManager.AppendResponseCookie(context, key, value, options);
            }
            catch (Exception ex)
            {
                if (context.Request.Uri.AbsolutePath == "/" && ex.Message.StartsWith("Server cannot append header after HTTP headers have been sent"))
                    throw new Exception("Owin CookieManager attempted to write headers to root response.", ex);
                else
                    throw;
            }
        }

        public void DeleteCookie(IOwinContext context, string key, CookieOptions options)
        {
            _chunkingCookieManager.DeleteCookie(context, key, options);
        }
    }


Conclusion

Hopefully Microsoft will fix their code some day.  However it has been a known issue since June 2017, and so far they have only made excuses for why they do not feel like fixing it.  So until it actually makes it onto their road map, these appear to be the best options for dealing with the issue.

As a quick note.  I read that Server.Transfer and Server.Execute also trigger this parent/child request feature of IIS.  If that is true, then they should also trigger this bug.  However, in my testing with Server.Transfer, I was not able to trip this bug.