aliostad / CacheCow

An implementation of HTTP Caching in .NET Core and 4.5.2+ for both the client and the server
MIT License
847 stars 172 forks source link

Writing to the response body is invalid for responses with status code 304. #241

Closed rtwilliams closed 4 years ago

rtwilliams commented 4 years ago

When I test with Postman sending the If-None-Match value, I get the 304 response code, but my Asp Core app logs the following error: Writing to the response body is invalid for responses with status code 304.

Here is the stack trace: [2019-11-26 15:27:43 Error] - 0HLRIMTOD75D9:00000002 -> Microsoft.AspNetCore.Server.Kestrel : Connection id ""0HLRIMTOD75D9"", Request id ""0HLRIMTOD75D9:00000002"": An unhandled exception was thrown by the application. System.InvalidOperationException: Writing to the response body is invalid for responses with status code 304. at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ThrowWritingToResponseBodyNotSupported() at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.WriteAsync(ReadOnlyMemory1 data, CancellationToken cancellationToken) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken) at System.IO.MemoryStream.CopyToAsync(Stream destination, Int32 bufferSize, CancellationToken cancellationToken) at CacheCow.Server.CachingPipeline.After(HttpContext context, Object viewModel) at CacheCow.Server.Core.Mvc.HttpCacheFilter.OnResourceExecutionAsync(ResourceExecutingContext context, ResourceExecutionDelegate next) at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeNextResourceFilter() at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Rethrow(ResourceExecutedContext context) at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted) at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeFilterPipelineAsync() at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeAsync() at Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(HttpContext httpContext) at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context) at AspNetCoreRateLimit.RateLimitMiddleware1.Invoke(HttpContext context) at Microsoft.AspNetCore.Server.IISIntegration.IISMiddleware.Invoke(HttpContext httpContext) at Microsoft.AspNetCore.Builder.Extensions.UsePathBaseMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)

aliostad commented 4 years ago

Hi,

Would you be able to send a repro? Also please mention:

If repro is not possible, a simple code example would be useful.

Gurubg1 commented 4 years ago

Hi, Same issue here. ASP.NET Core version 3.0.100 Cachecow version 2.5.8

rtwilliams commented 4 years ago

I'm just simply adding the HttpCacheFactory attribute to a API controller endpoint method. So if the client adds If-None-Match value to the request header and it matches the ETag value of the data requested, then the 304 not modified is returned. When this occurs it seems the CacheCow code is trying to write to the response body, which is not supported for a 304 response.

Here's code for registration in Startup.cs:

services.AddHttpCachingMvc();

Here's attribute example:

[HttpGet("{username}")]
[HttpCacheFactory(900)]
public async Task<ActionResult<AccountForApi>> GetByUsernameAsync(string username)
{
...
}

.Net version: Core 2.2 CacheCow version: 2.5.8

aliostad commented 4 years ago

The strange thing is I have lots of integration tests covering this. OK, I will have a look and get back to you within a day or two. Thanks once again for raising.

aliostad commented 4 years ago

Where are you running it. I am not able to reproduce.

I created a fresh ASP.NET Core MVC API on Windows and it just works. I slightly modified the sample Weather Forecast so that it keep sending back the same values.

Are you using IIS? Mine is IIS Express, although not sure if it is relevant,

using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;
using CacheCow.Server.Core.Mvc;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;

namespace WebApplication1.Controllers
{
    [ApiController]
    [Route("[controller]")]
    public class WeatherForecastController : ControllerBase
    {
        private static readonly string[] Summaries = new[]
        {
            "Freezing", "Bracing", "Chilly", "Cool", "Mild", "Warm", "Balmy", "Hot", "Sweltering", "Scorching"
        };

        private readonly ILogger<WeatherForecastController> _logger;

        public WeatherForecastController(ILogger<WeatherForecastController> logger)
        {
            _logger = logger;
        }

        [HttpGet]
        [HttpCacheFactory(900)]
        public async Task<IEnumerable<WeatherForecast>> GetAsync()
        {
            var rng = new Random(123);
            return Enumerable.Range(1, 5).Select(index => new WeatherForecast
            {
                Date = DateTime.Now.Date.AddDays(index),
                TemperatureC = rng.Next(-20, 55),
                Summary = Summaries[rng.Next(Summaries.Length)]
            })
            .ToArray();
        }
    }
}
aliostad commented 4 years ago

The easiest way would be to create a github repo with the repro, and I will test it.

aliostad commented 4 years ago

Hi @rtwilliams @Gurubg1 did you have a chance to look again? I actually have test cases for this, also samples all work. As I explained, I just created a new project with .NET Core and it just worked. Considering two people experienced this I believe there could be a problem it is just I am not able to reproduce.

rtwilliams commented 4 years ago

I'll try and reproduce with a new project. Should be able to do that today. Thanks for the responses.

rtwilliams commented 4 years ago

Tried to reproduce by creating another project. Could not reproduce. Then I tried stripping out everything but CacheCow and Serilog for the project the issue is occuring. Still could not rectify 304 error logging. I'm not sure how this is occuring. This is not a high priority for me, so I'm going to leave it here.

aliostad commented 4 years ago

Thanks for looking into.

I have a feeling this has to do with the optimisations that the ASP.NET team have done in terms of sending the headers early. This creates a variety of problems in CacheCow and I have discussed this at length with David Fowler and he promised to add an option to turn it off but it has not been done.

It might also be something different but due to its inconsistent occurrence, I think it is that.

Anyway, I will keep the issue open and try to build a testbed for it to try under varying load.

rtwilliams commented 4 years ago

FYI: Ok, so after some testing, this issue does not occur on my local machine, which use IIS version:

image

But does occur on our test server, which has an older IIS version installed: image

rtwilliams commented 4 years ago

Well, actually, when I deployed manually I do not get the 304 error on our dev server. So this may be an Azure Devops deployment issue.

rtwilliams commented 4 years ago

Found It! I had not updated my web.config when migrating from aspnetcore 2.1 to 2.2, There is a change that needs to made to the handler aspNetCore: the modules property needs to reference "AspNetCoreModuleV2".

Here is a link explaining the changes: https://discuss.newrelic.com/t/relic-solution-changes-with-net-core-2-2-and-aspnetcoremodulev2/65232

aliostad commented 4 years ago

Thank you! Well I had absolutely no idea about this, still pretty confused why it should happen. I leave it open until you re-test and run for a few days to make sure it is unrelated to CacheCow.

Gurubg1 commented 4 years ago

Same. worked for me when I upgraded to latest packages of cachecow. Thanks!!

Gurubg1 commented 4 years ago

I have another question, do we need to change anything in our front end angular code to support this? Whats happening is, chrome browser does not show a 304 status code. It shows 200 response with empty content due to which feature is not working properly.

Gurubg1 commented 4 years ago

Please ignore above comment. It was due to presence of Authorization header.

aliostad commented 4 years ago

Closing the issue. Please let me know if it ever happens again.

Nuschler commented 4 years ago

I am able to reproduce this issue as well running the project with console window (not IIS)

https://github.com/Nuschler/CacheCow

To reproduce run new sample in branch nuschler/241_ResponseBody304 https://github.com/Nuschler/CacheCow/tree/nuschler/241_ResponseBody304/samples/CacheCow.Samples.Issue241.MvcCore

I was able to make it go away by updating line 228 to check for status code 304 in CachingPipeline.cs (see branch nuschler/241_Fix) https://github.com/Nuschler/CacheCow/blob/nuschler/241_Fix/src/CacheCow.Server/CachingPipeline.cs

aliostad commented 4 years ago

thanks @Nuschler ! I will try to run and see the things.

aliostad commented 4 years ago

Hi @Nuschler not sure how to reproduce. I ran the code to bring up the server and used curl to call the server with If-None-Match and it just works. I got no error and 304 was returned to me:

> curl "http://localhost:5000/weatherforecast" -v -H "If-None-Match: \"FU7mawDqBWQ6BdgfAClFXegW07g/f/4rRY/WrCL8Wn8=\""
*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 5000 (#0)
> GET /weatherforecast HTTP/1.1
> Host: localhost:5000
> User-Agent: curl/7.55.1
> Accept: */*
> If-None-Match: "FU7mawDqBWQ6BdgfAClFXegW07g/f/4rRY/WrCL8Wn8="
>
< HTTP/1.1 304 Not Modified
< Date: Sun, 02 Feb 2020 17:22:07 GMT
< Content-Type: application/json; charset=utf-8
< Server: Kestrel
< Vary: Accept
< x-cachecow-server: validation-applied=True;validation-matched=True;short-circuited=False;query-made=False
<
* Connection #0 to host localhost left intact
aliostad commented 4 years ago

I have a feeling something is definitely wrong and needs fixing but frustrated not being able to reproduce.

Nuschler commented 4 years ago

I added logging to txt file in my sample project CacheCow.Samples.Issue241.MvcCore.

It appears the exception doesn't prevent the correct response to be returned, but you can see in the console output or log file that there is an exception in kestrel.

It looks like this is true on a 304 (length > 0 but it's just white space though)

bool mustReflush = ms != null && ms.Length > 0;

It still sends the response correctly but quietly there is an exception attempting to write to body on a 304 response.

I'm running VS 2019, .NET Core 3.1

Nuschler commented 4 years ago

Checking for 304 Response prevents the deeper exception. Haven;t dug in to see what is causing ms.Length > 0 though.

finally { if (mustReflush && context.Response.StatusCode != StatusCodes.Status304NotModified) { ms.Position = 0; await ms.CopyToAsync(context.Response.Body); } }

aliostad commented 4 years ago

Thanks, that is more insight. I should be able to understand it.

aliostad commented 4 years ago

Thanks everyone! I can reproduce now. I will be posting the fix in the next couple of days. The solution could be what @Nuschler implemented but need to understand more of the nature of the issue.

aliostad commented 4 years ago

OK, it seems to be a warning and that is why everything seems to work fine. There is an error as well but it just does not seem to cause a problem.

Regardless, I will create a fix, I am currently investigating how to create a unit test for it to capture the warning.

image

aliostad commented 4 years ago

I think this angry tweet sums up the situation... https://twitter.com/aliostad/status/1232075169008627714?s=20

aliostad commented 4 years ago

Thanks everyone. I finally managed to create a failing test for it - and then fixed it. Available in v2.7.2 which is just released.