RedisConnectionException: SocketClosed after Dispose of ConnectionMultiplexer

[teemka]

Hi,

I've recently enabled logging in an application and during shutdown we are getting a lot of error logs RedisConnectionException: SocketClosed. They appear after ConnectionMultiplexer has been disposed (last command is QUIT). I have reproduced the issue in a simple console Program. I've tested it against other instances of Redis and it seems that it only happens with AWS. Those errors don't propagate to the user code but it's annoying that they appear.

Client information: Windows 10, nuget v2.7.20, .NET 8.0.2 Server information: Amazon ElastiCache Redis instance v7.0.7, clustering enabled, 3 shard, 6 nodes

Minimum code to reproduce:

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using StackExchange.Redis; 

var builder = new HostApplicationBuilder(); 

builder.Logging.AddSimpleConsole(x => x.IncludeScopes = true); 

using var host = builder.Build(); 

var loggerFactory = host.Services.GetRequiredService<ILoggerFactory>(); 

var configuration = new ConfigurationOptions
{
    EndPoints = { { "clustercfg.***.***.use1.cache.amazonaws.com", 6379 } },
    Ssl = true,
    Password = "***",
    LoggerFactory = loggerFactory,
}; 

await using var connection = ConnectionMultiplexer.Connect(configuration);

Logs from the execution:

info: StackExchange.Redis.ConnectionMultiplexer[0]
      Connecting (sync) on .NET 8.0.2 (StackExchange.Redis: v2.7.20.59961)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379,password=*****,ssl=True
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379/Interactive: Connecting...
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: BeginConnectAsync
info: StackExchange.Redis.ConnectionMultiplexer[0]
      1 unique nodes specified (with tiebreaker)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Allowing 1 endpoint(s) 00:00:05 to respond...
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Awaiting 1 available task completion(s) for 5000ms, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=0,Free=32767,Min=32,Max=32767), POOL: (Threads=4,QueuedItems=0,CompletedItems=18,Timers=2)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Configuring TLS
info: StackExchange.Redis.ConnectionMultiplexer[0]
      TLS connection established successfully using protocol: Tls12
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379/Interactive: Connected
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Server handshake
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Authenticating (password)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Setting client name: ***(SE.Redis-v2.7.20.59961)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Setting client lib/ver
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Auto-configuring...
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Flushing outbound buffer
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: OnEstablishingAsync complete
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Starting read
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Auto-configured (CLIENT) connection-id: 615888
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Auto-configured (INFO) version: 7.0.7
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: Cluster
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Response from clustercfg.***.***.use1.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 ***-0001-002.***.***.use1.cache.amazonaws.com:6379
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Response from clustercfg.***.***.use1.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes
info: StackExchange.Redis.ConnectionMultiplexer[0]
      clustercfg.***.***.use1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=32,Max=32767), POOL: (Threads=4,QueuedItems=0,CompletedItems=38,Timers=2)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Endpoint summary:
info: StackExchange.Redis.ConnectionMultiplexer[0]
        clustercfg.***.***.use1.cache.amazonaws.com:6379: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Task summary:
info: StackExchange.Redis.ConnectionMultiplexer[0]
        clustercfg.***.***.use1.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      ***-0001-001.***.***.use1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      ***-0001-002.***.***.use1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Allowing 2 endpoint(s) 00:00:04.3540000 to respond...
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Awaiting 2 available task completion(s) for 4354ms, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=32,Max=32767), POOL: (Threads=4,QueuedItems=0,CompletedItems=44,Timers=4)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      ***-0001-002.***.***.use1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      ***-0001-001.***.***.use1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      All 2 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=32,Max=32767), POOL: (Threads=6,QueuedItems=0,CompletedItems=81,Timers=0)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Endpoint summary:
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-001.***.***.use1.cache.amazonaws.com:6379: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-002.***.***.use1.cache.amazonaws.com:6379: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Task summary:
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-001.***.***.use1.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO)
info: StackExchange.Redis.ConnectionMultiplexer[0]
       ***-0001-002.***.***.use1.cache.amazonaws.com:6379: Returned with success as Cluster primary (Source: From command: ECHO)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Cluster: 16384 of 16384 slots covered
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Endpoint Summary:
info: StackExchange.Redis.ConnectionMultiplexer[0]
        clustercfg.***.***.use1.cache.amazonaws.com:6379: Cluster v7.0.7, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
info: StackExchange.Redis.ConnectionMultiplexer[0]
        clustercfg.***.***.use1.cache.amazonaws.com:6379: int ops=16, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=7, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
info: StackExchange.Redis.ConnectionMultiplexer[0]
        clustercfg.***.***.use1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+16=16 (1.60 ops/s; spans 10s); sub: 0+7=7 (0.70 ops/s; spans 10s)
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-002.***.***.use1.cache.amazonaws.com:6379: Cluster v7.0.7, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-002.***.***.use1.cache.amazonaws.com:6379: int ops=14, qu=0, qs=1, qc=0, wr=0, socks=1; sub ops=7, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-002.***.***.use1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+14=14 (1.40 ops/s; spans 10s); sub: 0+7=7 (0.70 ops/s; spans 10s)
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-001.***.***.use1.cache.amazonaws.com:6379: Cluster v7.0.7, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-001.***.***.use1.cache.amazonaws.com:6379: int ops=15, qu=0, qs=2, qc=0, wr=0, socks=1; sub ops=7, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
info: StackExchange.Redis.ConnectionMultiplexer[0]
        ***-0001-001.***.***.use1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+15=15 (1.50 ops/s; spans 10s); sub: 0+7=7 (0.70 ops/s; spans 10s)
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Starting heartbeat...
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Total connect time: 1,171 ms
fail: StackExchange.Redis.ConnectionMultiplexer[0]
      SocketClosed on ***-0001-002.***.***.use1.cache.amazonaws.com:6379/Subscription, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 7 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
      StackExchange.Redis.RedisConnectionException: SocketClosed on ***-0001-002.***.***.use1.cache.amazonaws.com:6379/Subscription, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 7 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
fail: StackExchange.Redis.ConnectionMultiplexer[0]
      SocketClosed on ***-0001-001.***.***.use1.cache.amazonaws.com:6379/Interactive, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 7 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
      StackExchange.Redis.RedisConnectionException: SocketClosed on ***-0001-001.***.***.use1.cache.amazonaws.com:6379/Interactive, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 7 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
fail: StackExchange.Redis.ConnectionMultiplexer[0]
      SocketClosed on clustercfg.***.***.use1.cache.amazonaws.com:6379/Interactive, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 7 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
      StackExchange.Redis.RedisConnectionException: SocketClosed on clustercfg.***.***.use1.cache.amazonaws.com:6379/Interactive, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 7 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
fail: StackExchange.Redis.ConnectionMultiplexer[0]
      SocketClosed on ***-0001-001.***.***.use1.cache.amazonaws.com:6379/Subscription, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 5 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
      StackExchange.Redis.RedisConnectionException: SocketClosed on ***-0001-001.***.***.use1.cache.amazonaws.com:6379/Subscription, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 5 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
fail: StackExchange.Redis.ConnectionMultiplexer[0]
      SocketClosed on clustercfg.***.***.use1.cache.amazonaws.com:6379/Subscription, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 4 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
      StackExchange.Redis.RedisConnectionException: SocketClosed on clustercfg.***.***.use1.cache.amazonaws.com:6379/Subscription, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 4 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
fail: StackExchange.Redis.ConnectionMultiplexer[0]
      SocketClosed on ***-0001-002.***.***.use1.cache.amazonaws.com:6379/Interactive, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 4 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961
      StackExchange.Redis.RedisConnectionException: SocketClosed on ***-0001-002.***.***.use1.cache.amazonaws.com:6379/Interactive, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 4 of 10 available, in: 0, last-heartbeat: never, global: 1s ago, v: 2.7.20.59961

[bgrainger]

I've tested it against other instances of Redis and it seems that it only happens with AWS.

I'm experiencing this with Azure Cache for Redis:

info: StackExchange.Redis.ConnectionMultiplexer[0]
      Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Starting heartbeat...
info: StackExchange.Redis.ConnectionMultiplexer[0]
      Total connect time: 391 ms
info: Program[0]
      Connected to Redis
info: Program[0]
      Shutting down
fail: StackExchange.Redis.ConnectionMultiplexer[0]
      SocketClosed on HOST.redis.cache.windows.net:6380/Subscription, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 9 of 10 available, in: 0, last-heartbeat: never, global: 0s ago, v: 2.8.16.12844
      StackExchange.Redis.RedisConnectionException: SocketClosed on HOST.redis.cache.windows.net:6380/Subscription, Idle/MarkProcessed, last: QUIT, origin: ReadFromPipe, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 9 of 10 available, in: 0, last-heartbeat: never, global: 0s ago, v: 2.8.16.12844

it's annoying that they appear

I would like to keep spurious errors out of our logs; I don't want a "fail" to be logged if a graceful shutdown could happen instead.

[bgrainger]

It looks like SE.Redis tries to suppress error logging here: https://github.com/StackExchange/StackExchange.Redis/blob/00711481f92c06ccd4f83886e3d2b6e70718206b/src/StackExchange.Redis/PhysicalConnection.cs#L442-L443

However, that only works if pipe is SocketConnection, which will only occur if stream is null: https://github.com/StackExchange/StackExchange.Redis/blob/00711481f92c06ccd4f83886e3d2b6e70718206b/src/StackExchange.Redis/PhysicalConnection.cs#L1608-L1615

Which won't be true if we're using SSL: https://github.com/StackExchange/StackExchange.Redis/blob/00711481f92c06ccd4f83886e3d2b6e70718206b/src/StackExchange.Redis/PhysicalConnection.cs#L1556-L1566

This may be why @teemka reported that it only happens with AWS (and I'm encountering it with Azure): it's more typical to use SSL with PaaS Redis?