Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

RedisConnectionException: SocketClosed after Dispose of ConnectionMultiplexer #2652

Open
teemka opened this issue Feb 23, 2024 · 2 comments · May be fixed by #2814
Open

RedisConnectionException: SocketClosed after Dispose of ConnectionMultiplexer #2652

teemka opened this issue Feb 23, 2024 · 2 comments · May be fixed by #2814

Comments

@teemka
Copy link

teemka commented Feb 23, 2024

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 bgrainger mentioned this issue Nov 11, 2024
Closed
@bgrainger
Copy link

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
Copy link

It looks like SE.Redis tries to suppress error logging here:

StackExchange.Redis/src/StackExchange.Redis/PhysicalConnection.cs

Lines 442 to 443 in 0071148

// If the reason for the shutdown was we asked for the socket to die, don't log it as an error (only informational)
weAskedForThis = IsRequestedShutdown(sc.ShutdownKind);

However, that only works if pipe is SocketConnection, which will only occur if stream is null:

StackExchange.Redis/src/StackExchange.Redis/PhysicalConnection.cs

Lines 1608 to 1615 in 0071148

if (stream is not null)
{
pipe = StreamConnection.GetDuplex(stream, manager.SendPipeOptions, manager.ReceivePipeOptions, name: bridge.Name);
}
else
{
pipe = SocketConnection.Create(socket, manager.SendPipeOptions, manager.ReceivePipeOptions, name: bridge.Name);
}

Which won't be true if we're using SSL:

StackExchange.Redis/src/StackExchange.Redis/PhysicalConnection.cs

Lines 1556 to 1566 in 0071148

if (config.Ssl)
{
log?.LogInformation("Configuring TLS");
var host = config.SslHost;
if (host.IsNullOrWhiteSpace())
{
host = Format.ToStringHostOnly(bridge.ServerEndPoint.EndPoint);
}
stream ??= new NetworkStream(socket ?? throw new InvalidOperationException("No socket or stream available - possibly a tunnel error"));
var ssl = new SslStream(

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?

@bgrainger bgrainger linked a pull request Nov 11, 2024 that will close this issue
Open
bgrainger added a commit to Faithlife/StackExchange.Redis that referenced this issue Nov 11, 2024
@bgrainger
Track client-initiated shutdown for any pipe type. Fixes StackExchang…
966111f 
…e#2652
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Track client-initiated shutdown for any pipe type Faithlife/StackExchange.Redis
2 participants
@bgrainger @teemka