Issue with `ReThrowDistributedCacheExceptions`

[kory-revivemedia]

Hello!

I'm noticing that when using .WithDefaultEntryOptions and specifying ReThrowDistributedCacheExceptions set to false, that I'm still seeing distributed cache exceptions rethrown and logged (i.e. ILogger.LogError). The default value of ReThrowDistributedCacheExceptions is set to false, but noticing that it's not always honored. I want to recategorize distributed cache errors as warnings and not have them bubble up as errors in our logs/monitoring as they usually can be safely ignored.

Here's an example exception that's thrown and logged. I manually spun down my local redis instance to simulate redis issues.

ZiggyCreatures.Caching.Fusion.FusionCacheDistributedCacheException: An error occurred while working with the distributed cache
 ---> StackExchange.Redis.RedisConnectionException: The message timed out in the backlog attempting to send because no connection became available (5000ms) - Last Connection Exception: It was not possible to connect to the redis server(s). ConnectTimeout, command=HMGET, timeout: 5000, inst: 0, qu: 1, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 0, async-ops: 643, serverEndpoint: localhost:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: KORY-REVIVE(SE.Redis-v2.8.22.13109), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=22,Max=32767), POOL: (Threads=12,QueuedItems=0,CompletedItems=10613,Timers=20), v: 2.8.22.13109 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
 ---> StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout
   --- End of inner exception stack trace ---
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefreshAsync(String key, Boolean getData, CancellationToken token)
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAsync(String key, CancellationToken token)
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.<>c__DisplayClass14_0`1.<<TryGetEntryAsync>b__0>d.MoveNext() in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Async.cs:line 165
--- End of stack trace from previous location ---
   at ZiggyCreatures.Caching.Fusion.Internals.RunUtils.RunAsyncFuncWithTimeoutAsync[TResult](Func`2 asyncFunc, TimeSpan timeout, Boolean cancelIfTimeout, Action`1 timedOutTaskProcessor, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/RunUtils.cs:line 43
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.TryGetEntryAsync[TValue](String operationId, String key, FusionCacheEntryOptions options, Boolean hasFallbackValue, Nullable`1 timeout, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Async.cs:line 164
   --- End of inner exception stack trace ---
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.TryGetEntryAsync[TValue](String operationId, String key, FusionCacheEntryOptions options, Boolean hasFallbackValue, Nullable`1 timeout, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Async.cs:line 187

When setting a breakpoint at the throw location, I see that the value of options.ReThrowDistributedCacheExceptions is true:

Sample code that uses WithDefaultEntryOptions:

        services.AddFusionCache()
            .WithSystemTextJsonSerializer()
            .WithDistributedCache(CreateRedisCache())
            .WithRegisteredBackplane()
            .WithOptions(ConfigureFusionCacheOptions())
            .WithDefaultEntryOptions(options => { options.ReThrowDistributedCacheExceptions = false; });

[jodydonetti]

Hi @kory-revivemedia , what happens inside of ConfigureFusionCacheOptions() ?

[kory-revivemedia]

Hi @kory-revivemedia , what happens inside of ConfigureFusionCacheOptions() ?

    private static Action<FusionCacheOptions> ConfigureFusionCacheOptions() =>
        options =>
        {
            options.DistributedCacheErrorsLogLevel = LogLevel.Warning;
            options.BackplaneErrorsLogLevel = LogLevel.Warning;
        };

[jodydonetti]

Hi @kory-revivemedia , this is strange, and I've never seen this behaviour before.
I also have tests that check for this, and never caught something like this.

Are you sure you never set ReThrowDistributedCacheExceptions to true somewhere? If so, where/how?

In case this problems is still there, can you give me the call stack of the exception?

Thanks!

[kory-revivemedia]

@jodydonetti

Are you sure you never set ReThrowDistributedCacheExceptions to true somewhere? If so, where/how?

I double checked this and can confirm I'm only setting it to false in services registration.

Here's a full stack:

ZiggyCreatures.Caching.Fusion.FusionCacheDistributedCacheException: An error occurred while working with the distributed cache
 ---> StackExchange.Redis.RedisConnectionException: The message timed out in the backlog attempting to send because no connection became available (5000ms) - Last Connection Exception: It was not possible to connect to the redis server(s). ConnectTimeout, command=HMGET, timeout: 5000, inst: 0, qu: 1, qs: 0, aw: False, bw: CheckingForTimeout, rs: NotStarted, ws: Idle, in: 0, last-in: 0, cur-in: 0, sync-ops: 0, async-ops: 17, serverEndpoint: localhost:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: [REDACTED](SE.Redis-v2.8.22.13109), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=0,Free=32767,Min=22,Max=32767), POOL: (Threads=10,QueuedItems=0,CompletedItems=929,Timers=16), v: 2.8.22.13109 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
 ---> StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout
   --- End of inner exception stack trace ---
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefreshAsync(String key, Boolean getData, CancellationToken token)
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAsync(String key, CancellationToken token)
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.<>c__DisplayClass14_0`1.<<TryGetEntryAsync>b__0>d.MoveNext() in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Async.cs:line 165
--- End of stack trace from previous location ---
   at ZiggyCreatures.Caching.Fusion.Internals.RunUtils.RunAsyncFuncWithTimeoutAsync[TResult](Func`2 asyncFunc, TimeSpan timeout, Boolean cancelIfTimeout, Action`1 timedOutTaskProcessor, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/RunUtils.cs:line 43
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.TryGetEntryAsync[TValue](String operationId, String key, FusionCacheEntryOptions options, Boolean hasFallbackValue, Nullable`1 timeout, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Async.cs:line 164
   --- End of inner exception stack trace ---
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.TryGetEntryAsync[TValue](String operationId, String key, FusionCacheEntryOptions options, Boolean hasFallbackValue, Nullable`1 timeout, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Async.cs:line 187

Here's a sample Warning level log (w/ stack trace):

[08:18:28 WRN] FUSION [N=SHARED I=0HNAQANB5V4R9] (O=0HNAQANB5V4RT K=dev-shared:[REDACTED]): [DC] an error occurred while getting entry from distributed
StackExchange.Redis.RedisConnectionException: The message timed out in the backlog attempting to send because no connection became available (5000ms) - Last Connection Exception: It was not possible to connect to the r
edis server(s). ConnectTimeout, command=HMGET, timeout: 5000, inst: 0, qu: 1, qs: 0, aw: False, bw: CheckingForTimeout, rs: NotStarted, ws: Idle, in: 0, last-in: 0, cur-in: 0, sync-ops: 0, async-ops: 17, serverEndpoint
: localhost:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: [REDACTED](SE.Redis-v2.8.22.13109), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=0,Free=32767,Min=22,Max=32767), POOL:
 (Threads=10,QueuedItems=0,CompletedItems=929,Timers=16), v: 2.8.22.13109 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
 ---> StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout
   --- End of inner exception stack trace ---
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefreshAsync(String key, Boolean getData, CancellationToken token)
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAsync(String key, CancellationToken token)
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.<>c__DisplayClass14_0`1.<<TryGetEntryAsync>b__0>d.MoveNext() in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Async.cs:line 165
--- End of stack trace from previous location ---
   at ZiggyCreatures.Caching.Fusion.Internals.RunUtils.RunAsyncFuncWithTimeoutAsync[TResult](Func`2 asyncFunc, TimeSpan timeout, Boolean cancelIfTimeout, Action`1 timedOutTaskProcessor, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/RunUtils.cs:line 43
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.TryGetEntryAsync[TValue](String operationId, String key, FusionCacheEntryOptions options, Boolean hasFallbackValue, Nullable`1 timeout, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Async.cs:line 164

If it helps, I'm noticing mixed behavior between not rethrowing and throwing. It looks like sometimes the ReThrowDistributedCacheExceptions value is correctly set to false and I get Warning level logs and other times ReThrowDistributedCacheExceptions is set to true and I get Error level logs. Is there a default behavior somewhere that sets ReThrowDistributedCacheExceptions to true that I need to override somehow?

[jodydonetti]

Hi @kory-revivemedia , thanks for the details. Are you using Tagging?

It would be really really helpful if you'd be able to create an MRE. I know it's not always easy, but otherwise I would be looking at only FusionCache code, which is already covered by tests & so on.

Thanks.

[kory-revivemedia]

Are you using Tagging?

Yes, we are. Both on cache entries using factory methods and also cache expiration like RemoveByTagAsync.

if would be really really helpful if you'd be able to create an MRE. I know it's not always easy, but otherwise I would be looking at only FusionCache code, which is already covered by tests & so on.

I can take a look at some point if I get some extra time, but we've gotten around this issue by ignoring/silencing these exceptions from our alerts and monitors for now.

[kory-revivemedia]

@jodydonetti Tangentially related, but we're seeing these errors raised around Redis timeouts from our deployed API:

[Error] ZiggyCreatures.Caching.Fusion.FusionCache: FUSION [N=SHARED I=0HNAQBH45GDJS] (O=0HNAQBH45GI1J K=dev-shared:[REDACTED]): an error occurred while trying to update a memory entry from a distributed entry ZiggyCreatures.Caching.Fusion.FusionCacheDistributedCacheException: An error occurred while working with the distributed cache
 ---> StackExchange.Redis.RedisTimeoutException: Timeout performing HMGET (5000ms), next: HMGET v2:dev-shared:[REDACTED], inst: 6, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 28794, last-in: 0, cur-in: 0, sync-ops: 323, async-ops: 1469, serverEndpoint: [REDACTED]:6379, conn-sec: 2607.46, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: [REDACTED](SE.Redis-v2.8.22.13109), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=40,Free=32727,Min=2,Max=32767), POOL: (Threads=40,QueuedItems=461,CompletedItems=76586,Timers=12), v: 2.8.22.13109 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor`1 processor, ServerEndPoint server, T defaultValue) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2099
   at StackExchange.Redis.RedisDatabase.HashGet(RedisKey key, RedisValue[] hashFields, CommandFlags flags) in /_/src/StackExchange.Redis/RedisDatabase.cs:line 484
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefresh(String key, Boolean getData)
   at ZiggyCreatures.Caching.Fusion.Internals.RunUtils.RunSyncFuncWithTimeout[TResult](Func`2 syncFunc, TimeSpan timeout, Boolean cancelIfTimeout, Action`1 timedOutTaskProcessor, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/RunUtils.cs:line 252
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.TryGetEntry[TValue](String operationId, String key, FusionCacheEntryOptions options, Boolean hasFallbackValue, Nullable`1 timeout, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Sync.cs:line 156
   --- End of inner exception stack trace ---
   at ZiggyCreatures.Caching.Fusion.Internals.Distributed.DistributedCacheAccessor.TryGetEntry[TValue](String operationId, String key, FusionCacheEntryOptions options, Boolean hasFallbackValue, Nullable`1 timeout, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/Distributed/DistributedCacheAccessor_Sync.cs:line 179
   at ZiggyCreatures.Caching.Fusion.FusionCache.TryUpdateMemoryEntryFromDistributedEntry[TValue](String operationId, String key, FusionCacheMemoryEntry`1 memoryEntry) in /_/src/ZiggyCreatures.FusionCache/FusionCache_Sync.cs:line 1230

The interesting bit from this call stack is the _Sync methods being used, which I believe is potentially causing the number of threads "busy" in the pool to be much higher than expected. When troubleshooting this Redis timeout error specifically, one of the main contributors to this issue could be doing sync operations. During this time, there is a "burst" of activity during cache rebuilding. Is there a reason why it's using the _Sync instead of _Async versions? Could this be contributing to the odd value of ReThrowDistributedCacheExceptions?

[jodydonetti]

Hi @kory-revivemedia maybe I know where this is coming from, I'll check and will report back to you.

PS: on which version of FusionCache are you?

[kory-revivemedia]

Hi @kory-revivemedia maybe I know where this is coming from, I'll check and will report back to you.

PS: on which version of FusionCache are you?

Thanks for the update @jodydonetti. Looks like we're on version 2.1.0 of ZiggyCreatures.FusionCache, ZiggyCreatures.FusionCache.Backplane.StackExchangeRedis, and ZiggyCreatures.FusionCache.Serialization.SystemTextJson.

[jodydonetti]

Hi @kory-revivemedia , one last thing please, because I have a doubt.

When you said:

I'm noticing that when using .WithDefaultEntryOptions and specifying ReThrowDistributedCacheExceptions set to false, that I'm still seeing distributed cache exceptions rethrown and logged

you meant that you noticed some errors logged by FusionCache itself (but your application didn't notice anything) or that FusionCache did throw an exception that your application caught?

This is key for me to understand the problem.

Thanks.

[kory-revivemedia]

Hi @kory-revivemedia , one last thing please, because I have a doubt.

When you said:

I'm noticing that when using .WithDefaultEntryOptions and specifying ReThrowDistributedCacheExceptions set to false, that I'm still seeing distributed cache exceptions rethrown and logged

you meant that you noticed some errors logged by FusionCache itself (but your application didn't notice anything) or that FusionCache did throw an exception that your application caught?

This is key for me to understand the problem.

Thanks.

@jodydonetti

I don't believe the exception raised in my original message ever bubbled outside of FusionCache. We pivoted away from using FusionCache for a specific use case that generated these issues for now so I looked back a few weeks in our server logs and the common error message was:

ZiggyCreatures.Caching.Fusion.FusionCache: FUSION [N=SHARED I=0HNALK3ON695E] (O=0HNALK3ON6D8G K=[REDACTED]): an error occurred while trying to update a memory entry from a distributed entry

If I do a code search for that message, I see it in a few places: link. In both matches, it looks like FusionCache is caching the thrown exception and logging via logger.Log(LogLevel.Error, ....

Hope that helps.

[jodydonetti]

I don't believe the exception raised in my original message ever bubbled outside of FusionCache.

Ah! Now it makes sense, I thought it was being rethrown, since we were talking about the ReThrowDistributedCacheExceptions option.
You see, as the name implies that option drives the fact that a distributed cache exception is rethrown or not, not if it's logged.

So basically FusionCache is working as intended, correct?

We pivoted away from using FusionCache for a specific use case that generated these issues for now

Ok 🥲

so I looked back a few weeks in our server logs and the common error message was:
[...]
it looks like FusionCache is caching the thrown exception and logging via logger.Log(LogLevel.Error, ....

It's not caching the exception, it is just logging it for detective work later: those 2 code paths are internal, and are used when a backplane notification is received from another node, and FusionCache sees that the related cace entry is present in L1, and so it tries to update it from L2 to get the latest version. If that fails, you may end up having an out-of-sync L1 entry, so FusionCache logs that to let you know. Pratical example: you see that sometimes one node of your web cluster returns a different value from the other nodes, and you ask yourself "why?". You look at the logs, find that message, and now is clear.
This is the idea.
I may change that to not rethrow, and in that case I think it will log a warning instead of an error.

Thoughts?

Hope that helps.

Definitely, thanks!

[jodydonetti]

ps: I'm also looking at making the backplane even more async, so that in any case when receiving a backplane notification it will work better, in a less-blocking way (even though: that is background work, but still).

[kory-revivemedia]

Ah! Now it makes sense, I thought it was being rethrown, since we were talking about the ReThrowDistributedCacheExceptions option.
You see, as the name implies that option drives the fact that a distributed cache exception is rethrown or not, not if it's logged.

I suppose so; however, I think not rethrowing the exception would imply that it wouldn't be also logged as an error. Also, from my findings, the option itself was not set to false all the time, so that's still an issue. For more context, we were trying to suppress these logged errors to avoid noise in our alerting/logging when it wasn't an issue that needed someone's immediate attention.

It's not caching the exception, it is just logging it for detective work later: those 2 code paths are internal, and are used when a backplane notification is received from another node, and FusionCache sees that the related cace entry is present in L1, and so it tries to update it from L2 to get the latest version. If that fails, you may end up having an out-of-sync L1 entry, so FusionCache logs that to let you know. Pratical example: you see that sometimes one node of your web cluster returns a different value from the other nodes, and you ask yourself "why?". You look at the logs, find that message, and now is clear.
This is the idea.
I may change that to not rethrow, and in that case I think it will log a warning instead of an error.

This caching was a typo. I meant catching. Sorry 🙃

Ok 🥲

In the end, it wasn't FusionCache itself that was the problem... more of a symptom. I had refactored to use FusionCache for an existing caching pattern which we ended up changing. We still use FusionCache where it makes sense and it's been working well.

ps: I'm also looking at making the backplane even more async, so that in any case when receiving a backplane notification it will work better, in a less-blocking way (even though: that is background work, but still).

Sounds good. 👍

[jodydonetti]

I suppose so; however, I think not rethrowing the exception would imply that it wouldn't be also logged as an error.

Not necessarily strictly related, but I see your point. I'll probably change that, thanks for pointing out.

Also, from my findings, the option itself was not set to false all the time, so that's still an issue.

True, but that is because the specific operation is more of an internal one. But anyway, I got your point, makes sense.

For more context, we were trying to suppress these logged errors to avoid noise in our alerting/logging when it wasn't an issue that needed someone's immediate attention.

Damn, that's a good point, and a scenario I haven't thought about!

This caching was a typo. I meant catching. Sorry 🙃

Ahah ok

In the end, it wasn't FusionCache itself that was the problem... more of a symptom. I had refactored to use FusionCache for an existing caching pattern which we ended up changing. We still use FusionCache where it makes sense and it's been working well.

Great to know.

Anyway, it's important for me to grasp the expectations from the outside of my own bubble, so again thank you.

Will update you later.