Headers already sent in HttpSys response caching

[sksk571]

We are seeing occasional "Headers already sent" errors triggered from the HttpSys code that enables response caching:

ProcessRequestAsync System.InvalidOperationException: Headers already sent.
   at Microsoft.AspNetCore.Server.HttpSys.Response.CheckResponseStarted()
   at Microsoft.AspNetCore.Server.HttpSys.FeatureContext.ConsiderEnablingResponseCache()
   at Microsoft.AspNetCore.Server.HttpSys.FeatureContext.<OnResponseStart>d__131.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.AspNetCore.Server.HttpSys.MessagePump.<ProcessRequestAsync>d__23.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Microsoft.AspNetCore.Server.HttpSys.MessagePump.<ProcessRequestAsync>d__23.MoveNext()

[Tratcher]

Do you have a consistent repro for this? What app code generates this response? My best theory is that the app did something unsupported like writing to the response body inside the OnStarting event.

Here's the code for that stack trace.

https://github.com/aspnet/AspNetCore/blob/85e2147ff037cc9950249fbb9d095ad47ec4184a/src/Servers/HttpSys/src/RequestProcessing/Response.cs#L202-L213
https://github.com/aspnet/AspNetCore/blob/85e2147ff037cc9950249fbb9d095ad47ec4184a/src/Servers/HttpSys/src/RequestProcessing/Response.cs#L159-L167
https://github.com/aspnet/AspNetCore/blob/a784f4575b738ec5b7c6f5cfff2b1fee10de5118/src/Servers/HttpSys/src/FeatureContext.cs#L536-L545
https://github.com/aspnet/AspNetCore/blob/a784f4575b738ec5b7c6f5cfff2b1fee10de5118/src/Servers/HttpSys/src/FeatureContext.cs#L508-L517
https://github.com/aspnet/AspNetCore/blob/519ec839aff613406446af51303b9450230efc21/src/Servers/HttpSys/src/MessagePump.cs#L206-L207

[Tratcher]

Is the app calling Abort?
https://github.com/aspnet/AspNetCore/blob/a784f4575b738ec5b7c6f5cfff2b1fee10de5118/src/Servers/HttpSys/src/FeatureContext.cs#L446

[sksk571]

There is no consitent repro steps. The app is a simple tracking application that has a single controller action "/visit" which is called about 15 million times/day. The error in question appears once or twice a day while executing this action.
The application doesn't do anything unusual like calling Abort() or writing to response in OnStarting event. Besides of the mentioned controller action, there is just a couple of middleware components that modify request headers and do logging. I may provide their code if needed.

[Tratcher]

Lacking a repro, reviewing the middleware code is our next best option. Can you provide public or private access to the app code?

[sksk571]

Here is the middleware code:

public class ClientIdMiddleware
{
    private const string ClientIdHeader = "X-ClientId";
    private const string RecordIdQueryParameter = "RID";

    private readonly RequestDelegate _next;

    public ClientIdMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    public async Task Invoke(HttpContext httpContext)
    {
        var recordId = httpContext.Request.Query[RecordIdQueryParameter];
        if (!string.IsNullOrEmpty(recordId))
        {
            httpContext.Request.Headers[ClientIdHeader] = recordId;
        }

        await _next(httpContext);
    }
}

public class RequestCorrectorMiddleware
{
    private const string CLIENT_IP_HEADER = "X-CLIENT-IP";
    private const string CLOUDFLARE_IP_HEADER = "CF-Connecting-IP";

    private readonly RequestDelegate _next;

    public RequestCorrectorMiddleware(RequestDelegate next)
    {
        _next = next;
    }
    public async Task Invoke(HttpContext httpContext)
    {
        var header = httpContext.Request.Headers[CLOUDFLARE_IP_HEADER];

        if (string.IsNullOrWhiteSpace(header))
            header = httpContext.Request.Headers[CLIENT_IP_HEADER];

        if (!string.IsNullOrWhiteSpace(header))
        {
            httpContext.Connection.RemoteIpAddress = IPAddress.Parse(header);
        }

        await _next(httpContext);
    }
}

public class RequestLoggerMiddleware
{
    private readonly RequestDelegate _next;
    private readonly ILogger _logger;
    private readonly ISystemClock _clock;

    public RequestLoggerMiddleware(RequestDelegate next, ILogger<RequestLoggerMiddleware> logger, ISystemClock clock)
    {
        _next = next;
        _logger = logger;
        _clock = clock;
    }

    public async Task Invoke(HttpContext httpContext)
    {
        var activityId = Guid.NewGuid();
        AddActivityID(httpContext, activityId);
        var stopWatch = new Stopwatch();
        stopWatch.Start();
        try
        {
            await _next(httpContext);
        }
        catch (Exception)
        {
            if (!httpContext.Response.HasStarted)
                httpContext.Response.StatusCode = StatusCodes.Status500InternalServerError;
            throw;
        }
        finally
        {
            stopWatch.Stop();
            _logger.Log(LogLevel.Information, FormatLogMessage(httpContext, stopWatch.ElapsedMilliseconds));
        }
    }

    private static void AddActivityID(HttpContext httpContext, Guid activityId)
    {
        //this one to represent activityID in Error logs
        httpContext.Request.Headers.Add("X-Activity-ID", activityId.ToString("N"));
        httpContext.Response.Headers.Add("X-Activity-ID", activityId.ToString("N"));
    }

    private string FormatLogMessage(HttpContext httpContext, long elapsedMilliseconds)
    {
        var now = _clock.UtcNow.DateTime;
        return FormatLogMessage(
            $"{now:yyyy-MM-dd}",
            $"{now:HH:mm:ss}",
            $"{httpContext.Connection.LocalIpAddress}",
            $"{httpContext.Request.Method}",
            $"{httpContext.Request.Path}",
            $"{httpContext.Request.QueryString}",
            $"{httpContext.Connection.LocalPort}",
            "", //UserName in IIS
            $"{httpContext.Connection.RemoteIpAddress}",
            $"{httpContext.Request.Headers["User-Agent"]}",
            $"{httpContext.Request.Headers["Referer"]}",
            $"{httpContext.Request.Host}",
            $"{httpContext.Response.StatusCode}",
            "0", //Substatus in IIS
            "0", //Win32Status in IIS
            $"{elapsedMilliseconds}",
            $"{httpContext.Request.Headers["X-Activity-ID"]}",
            $"{httpContext.Request.Headers["CF-Connecting-IP"]}");
    }

    private string FormatLogMessage(params string[] items)
    {
        return string.Join(" ", items.Select(i => string.IsNullOrWhiteSpace(i) ? "-" : ReplaceWhiteSpaces(i)));
    }

    private string ReplaceWhiteSpaces(string s)
    {
        StringBuilder temp = new StringBuilder(s);
        for (int i = 0; i < temp.Length; i++)
        {
            if (char.IsWhiteSpace(temp[i]))
            {
                temp[i] = '+';
            }
        }
        return temp.ToString();
    }
}

[Tratcher]

You're right, those middleware look harmless. Looking at the stack trace, the response would have needed to complete without a body being written. Do you have the logs for what kind of response it was?

One possibility I see is if a cancellation token was used with retrieving the client cert, reading the request body, or writing to the response body, those would all abort the response and could trigger this.

https://github.com/aspnet/AspNetCore/search?q=RegisterForCancellation&unscoped_q=RegisterForCancellation

[sksk571]

There is no logs I'm afraid. Our web request logs are produced by RequestLoggerMiddleware above and it's never invoked in this case. However, this fact indicates that no response has been written, as request logging middleware is running before MVC controller, so controller has not been called. Here is how our Startup.Configure method looks like:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
    loggerFactory.AddNLog();

    app.Use((context, next) =>
    {
        context.Response.Headers.Add("Server", string.Empty);
        return next();
    });
    app.UseCors(a => a.AllowAnyHeader().AllowAnyMethod().AllowAnyOrigin().AllowCredentials());
    app.UseMiddleware<ClientIdMiddleware>();
    app.UseMiddleware<RequestLoggerMiddleware>();
    app.UseMiddleware<RequestCorrectorMiddleware>();
    app.UseStaticFiles();
    app.UseMvc();
}

[Tratcher]

I investigated a similar situation where the client was disconnecting during the request body upload. Here are the notes:

The first exception happens here in RequestStream.ReadAsync:
https://github.com/aspnet/AspNetCore/blob/b23ea5b6683b08e8d168ccf49e0fc8515077ee2e/src/Servers/HttpSys/src/RequestProcessing/RequestStream.cs#L388-L390
Just before it throws it calls Abort. This effectively aborts both the request and response.
https://github.com/aspnet/AspNetCore/blob/3ecdc403189a28e2f36723663f50e58c4637e3aa/src/Servers/HttpSys/src/RequestProcessing/Response.cs#L174
And once aborted, you can no longer modify the response.
https://github.com/aspnet/AspNetCore/blob/3ecdc403189a28e2f36723663f50e58c4637e3aa/src/Servers/HttpSys/src/RequestProcessing/Response.cs#L204-L207

@47th any chance your scenario was also a POST request where an exception had been thrown from the request body due to a client disconnect?

[sksk571]

The site is used for tracking with a lot of requests coming in, so there is a possibility that some clients are disconnecting before sending request completely. Most of requests are POST requests either with or without request body. This is a likely scenario I think.