Content-Length mismatch randomly on high throughput when using Output Caching

[vasicvuk]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

When using StackExchange Redis Output Caching we randomly get an error:

System.InvalidOperationException: Response Content-Length mismatch: too few bytes written (0 of 5468).

We analyzed the key value, and we see that the Content-Length is not part of the cache, this means that this 5468 is calculated from the cached entry, but for some reason, the response is not written and this error appears.

Output caching with Memory works without this issue.

UPDATE

The number of threads does not meter. The difference is the .NET Version (on the local we had Preview 7 and, on the environment, the latest nightly build). It seems the issue is introduced after RC1 version

Expected Behavior

No System.InvalidOperationException happening.

Steps To Reproduce

For the test, we created an Apache JMeter test with 10, 25, and 50 threads calling the API each of the tests contained this error.
We could reproduce the issue when using Output caching on the Debug level, only in the environment with the Docker container connecting to the Redis database.

Exceptions (if any)

No response

.NET Version

8.0.0-rc.2.23466.4

Anything else?

Host:
Version: 8.0.0-rc.2.23466.4
Architecture: x64
Commit: 287c10d253
RID: linux-musl-x64

.NET SDKs installed:
No SDKs were found.

.NET runtimes installed:
Microsoft.AspNetCore.App 8.0.0-rtm.23468.24 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.NETCore.App 8.0.0-rc.2.23466.4 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

Other architectures found:
None

Environment variables:
Not set

global.json file:
Not found

Learn more:
https://aka.ms/dotnet/info

Download .NET:
https://aka.ms/dotnet/download

[vasicvuk]

I verified that with .NET 8 Preview 7, we don't get this issue but on .NET 8 RC 2 (Nightly build or the latest RTM version) we get this issue.

It seems that this commit 0192968 resolved one but introduced the new issue.

As additional context, when the API is called within a single thread sequentially there is not this error. When I introduce a second parallel thread the issue occurs.

[vasicvuk]

@mgravell, @BrennanConroy Is there any chance you can take a look at this?

Thanks

[mgravell]

Well, dang. This is going to be a pain. Adding to my "things on fire" list for urgent investigation. I only saw this at the end of my day today - will be next working day to investigate.

[vasicvuk]

Thanks @mgravell

[BrennanConroy]

I was able to repro when going from preview7 of aspnetcore to rtm of aspnetcore. And I can repro without using Redis.

Looking into it a little since my work day is starting 😛

[vasicvuk]

@BrennanConroy Great news that you created repro, not sure why this is not happening to us with Memory variant.. But we use rc2 on env.

[mgravell]

@BrennanConroy well that just went from "bad" to "oh god"; I'm not at a PC so I can't jump on, sorry - my Monday isn't looking fun

[BrennanConroy]

Ok I think I found the bug, introduced in RC1 with #48328

The issue is that the OutputCacheEntry returned from

aspnetcore/src/Middleware/OutputCaching/src/OutputCacheMiddleware.cs

Line 345 in 36e03b5

cacheEntry = await _outputCacheEntryDispatcher.ScheduleAsync(cacheContext.CacheKey, (Store: _store, CacheContext: cacheContext), static async (key, state) => await OutputCacheEntryFormatter.GetAsync(key, state.Store, state.CacheContext.HttpContext.RequestAborted));

can be returned to multiple requests

aspnetcore/src/Middleware/OutputCaching/src/DispatcherExtensions.cs

Line 18 in 36e03b5

if (_workers.TryGetValue(key, out var task))

Which was done to reduce hitting the cache multiple times when serving the same cached response.
The problem is that we use potentially pooled memory in the OutputCacheEntry and want to clean up that pooled memory once we've served the request, so we dispose the OutputCacheEntry at

aspnetcore/src/Middleware/OutputCaching/src/OutputCacheMiddleware.cs

Line 118 in 36e03b5

context.ReleaseCachedResponse();

Which clears the body and headers which can cause any requests that are sharing the OutputCacheEntry to have odd behavior, like already setting the Headers but not having a body anymore, or not having headers or body and responding with an empty 200.

A couple possible fixes:

• Ref count in OutputCacheEntry so we don't dispose an in-use one
• Remove _outputCacheEntryDispatcher.ScheduleAsync(...) and always hit the cache so we don't share cache entries

[mgravell]

@BrennanConroy excellent investigative work; I'm inclined towards the former, to prevent alloc overhead - some kind of bool TryReuse() check returns true if and only if it can increment a counter i.e. it isn't already zero. A little awkward to implement though. I can look on Monday if you're not fancying a distraction.

The "oops we need to fix after rc2" isn't going to be a fun email to write, though ...