Redis cache timeout on multiple concurrent authenticated API requests due to retrieving dynamic claims cache for user? #8007 | Support

s.beckers created 2 months ago

ABP Framework version: v8.1.4
UI Type: Angular
Database System: EF Core (SQL Server)
Tiered (for MVC) or Auth Server Separated (for Angular): no

We're displaying some image thumbnails (+-100, 40/40px) on a web page, each image is retrieved from an authorized API endpoint. The API ends up crashing/unavailable due to Redis caching timeouts. K8S health checks fail, and API container reboots..

Stack trace: API log gets spammed with: +- 50 times:

2024-10-01 07:40:53Z [DBG] Get dynamic claims cache for user: c7356510-4d74-f816-9a7d-3a0624e8562a

+- 40 times:

2024-10-01 07:41:02Z [WRN] Timeout performing HMGET (5000ms), next: EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en, inst: 128, qu: 0, qs: 128, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 17250, in-pipe: 0, out-pipe: 0, last-in: 1, cur-in: 0, sync-ops: 573, async-ops: 5444, serverEndpoint: localhost:6379, conn-sec: 25,21, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=49,Free=32718,Min=20,Max=32767), POOL: (Threads=49,QueuedItems=4,CompletedItems=71543,Timers=18), v: 2.7.27.49176 (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.RedisTimeoutException: Timeout performing HMGET (5000ms), next: EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en, inst: 128, qu: 0, qs: 128, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 17250, in-pipe: 0, out-pipe: 0, last-in: 1, cur-in: 0, sync-ops: 573, async-ops: 5444, serverEndpoint: localhost:6379, conn-sec: 25,21, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=49,Free=32718,Min=20,Max=32767), POOL: (Threads=49,QueuedItems=4,CompletedItems=71543,Timers=18), v: 2.7.27.49176 (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 2105
   at StackExchange.Redis.RedisDatabase.HashGet(RedisKey key, RedisValue[] hashFields, CommandFlags flags) in /_/src/StackExchange.Redis/RedisDatabase.cs:line 407
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefresh(String key, Boolean getData)
   at Volo.Abp.Caching.DistributedCache`2.Get(TCacheKey key, Nullable`1 hideErrors, Boolean considerUow)
2024-10-01 07:41:02Z [WRN] ---------- Exception Data ----------
Redis-Message = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en
Redis-Message-Next = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en
Redis-OpsSinceLastHeartbeat = 128
Redis-Queue-Awaiting-Write = 0
Redis-Queue-Awaiting-Response = 128
Redis-Active-Writer = False
Redis-Backlog-Writer = SpinningDown
Redis-Read-State = ReadAsync
Redis-Write-State = Idle
Redis-Inbound-Bytes = 17250
Redis-Inbound-Pipe-Bytes = 0
Redis-Outbound-Pipe-Bytes = 0
Redis-Last-Result-Bytes = 1
Redis-Inbound-Buffer-Bytes = 0
Redis-Sync-Ops = 573
Redis-Async-Ops = 5444
Redis-Server-Endpoint = localhost:6379
Redis-Server-Connected-Seconds = 25,2
Redis-Abort-On-Connect = 0
Redis-Multiplexer-Connects = 1/1/0
Redis-Manager = 10 of 10 available
Redis-Client-Name = FZDNOT06(SE.Redis-v2.7.27.49176)
Redis-ThreadPool-IO-Completion = (Busy=0,Free=1000,Min=1,Max=1000)
Redis-ThreadPool-Workers = (Busy=49,Free=32718,Min=20,Max=32767)
Redis-ThreadPool-Items = (Threads=49,QueuedItems=4,CompletedItems=71543,Timers=18)
Redis-Busy-Workers = 49
Redis-Version = 2.7.27.49176
redis-command = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en
request-sent-status = Sent
redis-server = localhost:6379

Again +- 50 times:

2024-10-01 07:40:53Z [DBG] Get dynamic claims cache for user: c7356510-4d74-f816-9a7d-3a0624e8562a

+- 50 times:

2024-10-01 07:41:14Z [DBG] Added 0 entity changes to the current audit log

29 Answer(s)

0

Anjali_Musmade created 2 months ago
Support Team Support Team Member

Hello ,

Please check this similar issue https://github.com/StackExchange/StackExchange.Redis/issues/1120#issuecomment-818588316 and try the solution.

Thanks,
0

s.beckers created 2 months ago

Hi,

Just tested this, but adding sslprotocols=tls12 to the connection string didn't help. We're currently also not using Redis with SSL. We experience the issue also in localhost.

Best regards, Steff
0

Anjali_Musmade created 2 months ago
Support Team Support Team Member

Hello ,

Please check this https://abp.io/support/questions/5847/redis-commands-timeout

Thanks
0
s.beckers created 2 months ago
Thanks! Increasing the MinThreads seems to work:

public class Program { public static async Task<int> Main(string[] args) { try { ... System.Threading.ThreadPool.GetMinThreads(out int minWorkerThreads, out int minCompletionPortThreads); System.Threading.ThreadPool.SetMinThreads(minWorkerThreads * 50, minCompletionPortThreads * 50); ... } ... } }

I've tested this by multiplying the MinThreads with 50, resulting in 1000 worker threads and 50 completion port threads. I'm not sure if this is a best practice. Is 50 times too much? How should I choose a good amount of threads?

This might also result in some other issues according to Microsoft docs: https://learn.microsoft.com/en-us/dotnet/standard/threading/the-managed-thread-pool#thread-pool-minimums

Isn't this just a framework issue? Calling the cache too much? I would think that the managed thread pool should do it's job just fine, without adjusting the minimum of worker threads.
0

alper created 2 months ago
Support Team Director

I'll check this
0
liangshiwei created 2 months ago
Support Team Fullstack Developer
API log gets spammed with: +- 50 times:

2024-10-01 07:40:53Z [DBG] Get dynamic claims cache for user: c7356510-4d74-f816-9a7d-3a0624e8562a

Hi,

This should not be a problem; ABP only calls once in a HTTP request.

And you can try disable dynamic claims system to test it

context.Services.Configure<AbpClaimsPrincipalFactoryOptions>(options => { options.IsDynamicClaimsEnabled = false; });
0

alper created 2 months ago
Support Team Director

When you enable the Dynamic Claims feature, in each request, we read the claims (from Redis) of the request to check current permissions in the current session. If you disable it, when you revoke permission from a user, he needs to log out / log in to refresh his permissions.

s.beckers created 2 months ago

Thanks for the feedback!

Disabling dynamic claims (which we also don't want to) doesn't fix the issue. I see it's trying to retrieve & expire localizations from the cache?

Stack trace: API log gets spammed with: +- 50 times:

2024-10-02 11:01:19Z [WRN] The message timed out in the backlog attempting to send because no connection became available, command=HMGET, timeout: 5000, outbound: 0KiB, inbound: 1KiB, inst: 0, qu: 37, qs: 0, aw: True, bw: CheckingForTimeoutComplete, rs: ReadAsync, ws: Idle, in: 0, in-pipe: 0, out-pipe: 0, last-in: 1, cur-in: 0, sync-ops: 448, async-ops: 4074, serverEndpoint: localhost:6379, conn-sec: 31,24, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=39,Free=32728,Min=20,Max=32767), POOL: (Threads=39,QueuedItems=47,CompletedItems=68595,Timers=15), v: 2.7.27.49176 (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.RedisTimeoutException: The message timed out in the backlog attempting to send because no connection became available, command=HMGET, timeout: 5000, outbound: 0KiB, inbound: 1KiB, inst: 0, qu: 37, qs: 0, aw: True, bw: CheckingForTimeoutComplete, rs: ReadAsync, ws: Idle, in: 0, in-pipe: 0, out-pipe: 0, last-in: 1, cur-in: 0, sync-ops: 448, async-ops: 4074, serverEndpoint: localhost:6379, conn-sec: 31,24, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=39,Free=32728,Min=20,Max=32767), POOL: (Threads=39,QueuedItems=47,CompletedItems=68595,Timers=15), v: 2.7.27.49176 (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 2105
   at StackExchange.Redis.RedisDatabase.HashGet(RedisKey key, RedisValue[] hashFields, CommandFlags flags) in /_/src/StackExchange.Redis/RedisDatabase.cs:line 407
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefresh(String key, Boolean getData)
   at Volo.Abp.Caching.DistributedCache`2.Get(TCacheKey key, Nullable`1 hideErrors, Boolean considerUow)
2024-10-02 11:01:19Z [WRN] ---------- Exception Data ----------
Redis-Message = HMGET t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:ExternalPortal_en-BE
Redis-Timeout = 5000
Redis-Write-State = Idle
Redis-Read-State = ReadAsync
Redis-OutboundDeltaKB = 0KiB
Redis-InboundDeltaKB = 1KiB
Redis-OpsSinceLastHeartbeat = 0
Redis-Queue-Awaiting-Write = 37
Redis-Queue-Awaiting-Response = 0
Redis-Active-Writer = True
Redis-Backlog-Writer = CheckingForTimeoutComplete
Redis-Inbound-Bytes = 0
Redis-Inbound-Pipe-Bytes = 0
Redis-Outbound-Pipe-Bytes = 0
Redis-Last-Result-Bytes = 1
Redis-Inbound-Buffer-Bytes = 0
Redis-Sync-Ops = 448
Redis-Async-Ops = 4074
Redis-Server-Endpoint = localhost:6379
Redis-Server-Connected-Seconds = 31,24
Redis-Abort-On-Connect = 0
Redis-Multiplexer-Connects = 1/1/0
Redis-Manager = 10 of 10 available
Redis-Client-Name = FZDNOT06(SE.Redis-v2.7.27.49176)
Redis-ThreadPool-IO-Completion = (Busy=0,Free=1000,Min=1,Max=1000)
Redis-ThreadPool-Workers = (Busy=39,Free=32728,Min=20,Max=32767)
Redis-ThreadPool-Items = (Threads=39,QueuedItems=47,CompletedItems=68595,Timers=15)
Redis-Busy-Workers = 39
Redis-Version = 2.7.27.49176
redis-command = HMGET t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:ExternalPortal_en-BE
request-sent-status = WaitingInBacklog
redis-server = localhost:6379

+- 50 times:

2024-10-02 11:01:37Z [WRN] Timeout performing EXPIRE (5000ms), next: EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en, inst: 28, qu: 0, qs: 28, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 1060, in-pipe: 0, out-pipe: 0, last-in: 0, cur-in: 0, sync-ops: 674, async-ops: 4074, serverEndpoint: localhost:6379, conn-sec: 49,66, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=66,Free=32701,Min=20,Max=32767), POOL: (Threads=66,QueuedItems=25,CompletedItems=68718,Timers=14), v: 2.7.27.49176 (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.RedisTimeoutException: Timeout performing EXPIRE (5000ms), next: EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en, inst: 28, qu: 0, qs: 28, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 1060, in-pipe: 0, out-pipe: 0, last-in: 0, cur-in: 0, sync-ops: 674, async-ops: 4074, serverEndpoint: localhost:6379, conn-sec: 49,66, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=66,Free=32701,Min=20,Max=32767), POOL: (Threads=66,QueuedItems=25,CompletedItems=68718,Timers=14), v: 2.7.27.49176 (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 2105
   at StackExchange.Redis.RedisDatabase.KeyExpire(RedisKey key, Nullable`1 expiry, ExpireWhen when, CommandFlags flags) in /_/src/StackExchange.Redis/RedisDatabase.cs:line 840
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.Refresh(IDatabase cache, String key, Nullable`1 absExpr, Nullable`1 sldExpr)
   at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefresh(String key, Boolean getData)
   at Volo.Abp.Caching.DistributedCache`2.Get(TCacheKey key, Nullable`1 hideErrors, Boolean considerUow)
2024-10-02 11:01:37Z [WRN] ---------- Exception Data ----------
Redis-Message = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en-BE
Redis-Message-Next = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en
Redis-OpsSinceLastHeartbeat = 28
Redis-Queue-Awaiting-Write = 0
Redis-Queue-Awaiting-Response = 28
Redis-Active-Writer = False
Redis-Backlog-Writer = SpinningDown
Redis-Read-State = ReadAsync
Redis-Write-State = Idle
Redis-Inbound-Bytes = 1060
Redis-Inbound-Pipe-Bytes = 0
Redis-Outbound-Pipe-Bytes = 0
Redis-Last-Result-Bytes = 0
Redis-Inbound-Buffer-Bytes = 0
Redis-Sync-Ops = 674
Redis-Async-Ops = 4074
Redis-Server-Endpoint = localhost:6379
Redis-Server-Connected-Seconds = 49,66
Redis-Abort-On-Connect = 0
Redis-Multiplexer-Connects = 1/1/0
Redis-Manager = 10 of 10 available
Redis-Client-Name = FZDNOT06(SE.Redis-v2.7.27.49176)
Redis-ThreadPool-IO-Completion = (Busy=0,Free=1000,Min=1,Max=1000)
Redis-ThreadPool-Workers = (Busy=66,Free=32701,Min=20,Max=32767)
Redis-ThreadPool-Items = (Threads=66,QueuedItems=25,CompletedItems=68718,Timers=14)
Redis-Busy-Workers = 66
Redis-Version = 2.7.27.49176
redis-command = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en-BE
request-sent-status = Sent
redis-server = localhost:6379

+- 50 times:

2024-10-02 11:01:41Z [DBG] Added 0 entity changes to the current audit log

0

alper created 2 months ago
Support Team Director

ok then we'll look deeper into this issue
0

maliming created 2 months ago
Support Team Fullstack Developer

Hi

I see it's trying to retrieve & expire localizations from the cache?

Please share full http request debug logs of this exception.

Thanks
0

s.beckers created 2 months ago

@maliming Can I send the full log to you by email?
0

maliming created 2 months ago
Support Team Fullstack Developer

sure, liming.ma@volosoft.com
0

s.beckers created 2 months ago

sure, liming.ma@volosoft.com

I've just sent you the full log by email.

maliming created 2 months ago

Support Team Fullstack Developer

Please try to remove DynamicLocalizationResourceContributor and try again.

    public override void ConfigureServices(ServiceConfigurationContext context)
    {
        PostConfigure<AbpLocalizationOptions>(options =>
        {
            options.GlobalContributors.Remove<DynamicLocalizationResourceContributor>();
        });
    }

0

s.beckers created 2 months ago

Please try to remove DynamicLocalizationResourceContributor and try again.

That does the job! Removing the DynamicLocalizationResourceContributor from the language management module gives a big performance boost. Which functionality do we lose by removing this?
0

maliming created 2 months ago
Support Team Fullstack Developer

You can't use dynamic localization texts from database without DynamicLocalizationResourceContributor
0

s.beckers created 2 months ago

I just found this related question: https://abp.io/support/questions/2880/Redis-performance-issues-in-LanguageManagement-DynamicLocalizationResourceContributor
0

maliming created 2 months ago
Support Team Fullstack Developer

hi

This may be a problem caused by the async API.

I will check it later.

2
0

s.beckers created 2 months ago

Is this added to the backlog? Just asking since ServiceBot would like to close this question..
0

maliming created 2 months ago
Support Team Fullstack Developer

I will check it. You can ignore the bot, I will reply you when I have result.

1
0

maliming created 2 months ago
Support Team Fullstack Developer

hi @s.beckers

Can you share your test project?

liming.ma@volosoft.com

Thanks.
0

s.beckers created 2 months ago

hi @s.beckers

Can you share your test project?

liming.ma@volosoft.com

Thanks.

Hi @maliming, I'll try to create a test project and send it to you.
0

maliming created 2 months ago
Support Team Fullstack Developer

Thanks 🙏
0
s.beckers created 2 months ago
Hi @maliming, I've tried to create a test app, but I couldn't reproduce the same warnings we got from the Redis timeouts. We monitored the thread pool usage:

dotnet-counters monitor --counters System.Runtime -n Fuzed.HttpApi.Host

In the end we ended up updating the min worker threads in our app:

ThreadPool.GetMinThreads(out int minWorkerThreads, out int minCompletionPortThreads); ThreadPool.SetMinThreads(100, minCompletionPortThreads);

Thanks!
0

maliming created 2 months ago
Support Team Fullstack Developer

Can you reproduce the error without SetMinThreads?

Showing 1 to 25 of 29 entries.

Previous
1 (current)
2
Next

Have an answer to this question? Log in and write your answer.