Open Closed

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


User avatar
0
s.beckers created
  • 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)
  • User Avatar
    0
    Anjali_Musmade created
    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,

  • User Avatar
    0
    s.beckers created

    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

  • User Avatar
    0
    Anjali_Musmade created
    Support Team Support Team Member

    Hello ,

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

    Thanks

  • User Avatar
    0
    s.beckers created

    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.

  • User Avatar
    0
    alper created
    Support Team Director

    I'll check this

  • User Avatar
    0
    liangshiwei created
    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;
    });
    
  • User Avatar
    0
    alper created
    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.

  • User Avatar
    0
    s.beckers created

    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
    
  • User Avatar
    0
    alper created
    Support Team Director

    ok then we'll look deeper into this issue

  • User Avatar
    0
    maliming created
    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

  • User Avatar
    0
    s.beckers created

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

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

    sure, liming.ma@volosoft.com

  • User Avatar
    0
    s.beckers created

    sure, liming.ma@volosoft.com

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

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

    hi

    Please try to remove DynamicLocalizationResourceContributor and try again.

        public override void ConfigureServices(ServiceConfigurationContext context)
        {
            PostConfigure<AbpLocalizationOptions>(options =>
            {
                options.GlobalContributors.Remove<DynamicLocalizationResourceContributor>();
            });
        }
    
  • User Avatar
    0
    s.beckers created

    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?

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

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

  • User Avatar
    0
    s.beckers created

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

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

    hi

    This may be a problem caused by the async API.

    I will check it later.

  • User Avatar
    0
    s.beckers created

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

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

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

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

    hi @s.beckers

    Can you share your test project?

    liming.ma@volosoft.com

    Thanks.

  • User Avatar
    0
    s.beckers created

    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.

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

    Thanks 🙏

  • User Avatar
    0
    s.beckers created

    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!

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

    Can you reproduce the error without SetMinThreads?

Made with ❤️ on ABP v9.1.0-preview. Updated on November 01, 2024, 05:35