sure, liming.ma@volosoft.com
I've just sent you the full log by email.
@maliming Can I send the full log to you by email?
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
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.
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
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
Hi,
Problem solved by upgrading ABP packages to v8.1.4. Thanks!
Hi,
I think the following is the related code which is logging to the console:
This triggers on handling an event handler:
public virtual async Task HandleEventAsync(EntityUpdatedEto<CompanyEto> eventData)
{
...
}
Do I need some configuration on the CompanyEto itself then?
[Audited]
public class Company : FullAuditedAggregateRoot<Guid>, IMultiTenant
{
...
public Company(
Guid id,
string name)
{
Id = id;
Name = name;
}
...
public Address? Address { get; set; }
...
public virtual ICollection<CompanyEmail> Emails { get; private set; } = new Collection<CompanyEmail>();
...
}
And the following handler:
public virtual async Task HandleEventAsync(EntityUpdatedEto<CompanyEto> eventData)
{
...
}
When we make an update in the Address (owned entity) or make changes to the Emails list and then updating the company by:
await _companyRepository.UpdateAsync(company);
The event handler is not triggered anymore since the upgrade to v8.1.1. Any idea why?