Massive SocketClosed Exceptions and ConnectionRestored with hanging requests

[KoPoKonstantin]

Hi,

we are experiencing Problems with our Redis Clients in production under heavy load.
Directly when starting the applications the ConnectionPoolManager starts to throw Exception Logs from their StateAwareConnection handles.
I connected a Custom ILoggerFactory to get the log of the library into our service logfiles and am seeing those massive Socket Closed and Connection Restored entries in only a few milliseconds.

We are experience requests, which just hang waiting for the async response of their redis request, but some never return until timeouts or take multiple seconds to answer. Most of the requests are answered in milliseconds, as expected.

We started to see this behaviour, when upgrading our servies from .net 4.8 (where the problems did not occur) to .net 6.

Can someone point out any ideas where these Socket Closed Exceptions can come from? The redis statistics say the load is not the problem. CPU and RAM also fine and low. When those hangs and long waittimes (together with the exceptions) occur, the CPU normally drops down to a few % (only waiting for answers from the connectionMultiplexer).

lib version: 2.7.33
used functions: StringGetAsync and StringSetAsync, nothing else.
Poolsize: 5
Using the ConnectionPoolManager for Round Robin ConnectionMultiplexer.
Highly parallel usage of these Connections.

See attached screenshot for some example.

redis-failuretype=SocketClosed,redis-endpoint=192.168.47.191:6379,redis-origin=ReadFromPipe,redis-outstanding-responses=0,redis-last-read="0s ago",redis-last-write="11s ago",redis-keep-alive=60s,redis-previous-physical-state=ConnectedEstablished,redis-manager="7 of 8 available",redis-inbound-bytes=0,redis-inbound-pipe-bytes=0,redis-outbound-pipe-bytes=0,redis-last-heartbeat="0s ago",redis-last-multiplexer-heartbeat="0s ago",redis-last-global-heartbeat="0s ago",redis-version=2.7.33.41805,ex=StackExchange.Redis.RedisConnectionException: SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.191:6379/Interactive, Idle/MarkProcessed, last: INFO, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 11s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 7 of 8 available, in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last...

log.txt

Thanks in Advance for any help.

[NickCraver]

Using the ConnectionPoolManager for Round Robin ConnectionMultiplexer.

Unfortunately, that's not something we're familiar with or control, but my first guess given your symptoms is that is re-creating multiplexers rather than letting them re-connect internally, likely spiking your socket counts too. I'd need to see the full exceptions (we're getting truncated there) and how long we've been connected to get a better idea. The full exception message will also contain some thread pool and queue data which is rather helpful in diagnosing these.

[KoPoKonstantin]

Hi Nick,

thanks for your answer. I can even reproduce this behaviour, when just using one instance of connectionmultiplexer, ignoring the ConnectionPoolManager.
I enabled some more debug information. Here is a full exception:

2024-04-23 17:16:51,582 level=ERROR,class=CustomRedisCacheService,id=4fd044dc-cef5-4b48-976c-bdb0cf17b16d,action=GetValueAsync,"StackExchange.Redis.RedisConnectionException: No connection is active/available to service this operation: TTL+GET Measurement.ApiMeas... It was not possible to connect to the redis server(s). ConnectTimeout, mc: 1/1/0, clientName: 47VMR02(SE.Redis-v2.7.33.41805), PerfCounterHelperkeyHashSlot: 4497, IOCP: (Busy=0,Free=1000,Min=4,Max=1000), WORKER: (Busy=241,Free=32526,Min=4,Max=32767), POOL: (Threads=361,QueuedItems=1186,CompletedItems=435500,Timers=35), v: 2.7.33.41805
---> System.AggregateException: One or more errors occurred. (It was not possible to connect to the redis server(s). ConnectTimeout) (It was not possible to connect to the redis server(s). ConnectTimeout) (It was not possible to connect to the redis server(s). ConnectTimeout) (It was not possible to connect to the redis server(s). ConnectTimeout) (It was not possible to connect to the redis server(s). ConnectTimeout) (It was not possible to connect to the redis server(s). ConnectTimeout) (SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.162:6379/Interactive, Idle/MarkProcessed, last: SETEX, origin: ReadFromPipe, outstanding: 413, last-read: 0s ago, last-write: 0s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 108914, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805) (SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.192:6379/Interactive, Idle/MarkProcessed, last: GET, origin: ReadFromPipe, outstanding: 436, last-read: 0s ago, last-write: 0s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 110859, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805) (SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.191:6379/Interactive, Idle/MarkProcessed, last: GET, origin: ReadFromPipe, outstanding: 396, last-read: 0s ago, last-write: 0s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 62341, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805) (SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.195:6379/Interactive, Idle/MarkProcessed, last: INFO, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 27s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805) (SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.185:6379/Interactive, Idle/MarkProcessed, last: INFO, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 55s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805) (SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.187:6379/Interactive, Idle/MarkProcessed, last: INFO, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 27s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805)
---> StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout
--- End of inner exception stack trace ---
---> (Inner Exception #1) StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout<---

---> (Inner Exception #2) StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout<---

---> (Inner Exception #3) StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout<---

---> (Inner Exception #4) StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout<---

---> (Inner Exception #5) StackExchange.Redis.RedisConnectionException: It was not possible to connect to the redis server(s). ConnectTimeout<---

---> (Inner Exception #6) StackExchange.Redis.RedisConnectionException: SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.162:6379/Interactive, Idle/MarkProcessed, last: SETEX, origin: ReadFromPipe, outstanding: 413, last-read: 0s ago, last-write: 0s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 108914, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805
at Sma.Sp.Measurement.CustomRedisCacheService.SetValueAsync(CacheKey key, Object value, CacheExpiry expiry) in D:\Development\IguanaBL\BusinessCore\Sma.Sp.Measurement\Code\Sma.Sp.Measurement\CustomRedisCacheService.cs:line 169<---

---> (Inner Exception #7) StackExchange.Redis.RedisConnectionException: SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.192:6379/Interactive, Idle/MarkProcessed, last: GET, origin: ReadFromPipe, outstanding: 436, last-read: 0s ago, last-write: 0s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 110859, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805
at Sma.Sp.Measurement.CustomRedisCacheService.GetValueAsync(CacheKey cacheKey, Type responseType) in D:\Development\IguanaBL\BusinessCore\Sma.Sp.Measurement\Code\Sma.Sp.Measurement\CustomRedisCacheService.cs:line 80<---

---> (Inner Exception #8) StackExchange.Redis.RedisConnectionException: SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.191:6379/Interactive, Idle/MarkProcessed, last: GET, origin: ReadFromPipe, outstanding: 396, last-read: 0s ago, last-write: 0s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 62341, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805
at Sma.Sp.Measurement.CustomRedisCacheService.GetValueAsync(CacheKey cacheKey, Type responseType) in D:\Development\IguanaBL\BusinessCore\Sma.Sp.Measurement\Code\Sma.Sp.Measurement\CustomRedisCacheService.cs:line 80<---

---> (Inner Exception #9) StackExchange.Redis.RedisConnectionException: SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.195:6379/Interactive, Idle/MarkProcessed, last: INFO, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 27s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805<---

---> (Inner Exception #10) StackExchange.Redis.RedisConnectionException: SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.185:6379/Interactive, Idle/MarkProcessed, last: INFO, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 55s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805<---

---> (Inner Exception #11) StackExchange.Redis.RedisConnectionException: SocketClosed (ReadEndOfStream, last-recv: 0) on 192.168.47.187:6379/Interactive, Idle/MarkProcessed, last: INFO, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 27s ago, keep-alive: 3600000s, state: ConnectedEstablished, mgr: , in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.7.33.41805<---

--- End of inner exception stack trace ---
at StackExchange.Redis.ConnectionMultiplexer.ThrowFailed[T](TaskCompletionSource`1 source, Exception unthrownException) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2048
--- End of stack trace from previous location ---

[KoPoKonstantin]

worth mentioning, that the same connectionmultiplexer instance worked fine for several minutes before starting with this with answer times around 0-10 ms

[NickCraver]

It looks like you have some extreme thread exhaustion as indicated by WORKER: (Busy=241,Free=32526,Min=4,Max=32767), POOL: (Threads=361,QueuedItems=1186,CompletedItems=435500,Timers=35), this will be that tasks for connecting to Redis or completing commands get so far behind in the queue, they timeout before being completed (at the shared threadpool level). I'd suggest taking a dump and see what those hundreds of threads are doing, it's likely something's either locking or a remote call that should be async elsewhere in the application.