StackExchange / StackExchange.Redis

General purpose redis client
https://stackexchange.github.io/StackExchange.Redis/
Other
5.91k stars 1.51k forks source link

Client connection issue randomly #1986

Closed gurc4n closed 2 years ago

gurc4n commented 2 years ago

I have a redis server and client applications are using StackExchange.Redis nuget package. Randomly I am losing connection to Redis server with the exception below:

Exception in the client : [13:11:19.895] [ERR] { ThreadId: 60 } No connection is active/available to service this operation: GET CH:coreGetCNCDeviceByMachine-1947848840; An established connection was aborted by the software in your host machine, mc: 1/1/0, mgr: 10 of 10 available, clientName: XXXXXXXXXXXXX, IOCP: (Busy=0,Free=1000,Min=16,Max=1000), WORKER: (Busy=2,Free=32765,Min=16,Max=32767), v: 2.2.88.56325 StackExchange.Redis.RedisConnectionException: No connection is active/available to service this operation: GET CH:coreGetCNCDeviceByMachine-1947848840; An established connection was aborted by the software in your host machine, mc: 1/1/0, mgr: 10 of 10 available, clientName: EPDI-WEB01b71cfb44-36bf-4694-8a03-23c35315ff4c, IOCP: (Busy=0,Free=1000,Min=16,Max=1000), WORKER: (Busy=2,Free=32765,Min=16,Max=32767), v: 2.2.88.56325 ---> StackExchange.Redis.RedisConnectionException: SocketFailure (ReadEndOfStream, 0-read, last-recv: 0) on XXXXXXXXXXX/Subscription, Flushing/NotStarted, last: SUBSCRIBE, origin: OnEstablishingAsyncAwaited, outstanding: 3, last-read: 0s ago, last-write: 0s ago, keep-alive: 60s, state: ConnectedEstablishing, mgr: 10 of 10 available, last-heartbeat: never, global: 0s ago, v: 2.2.88.56325 ---> System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine at Pipelines.Sockets.Unofficial.Internal.Throw.Socket(Int32 errorCode) in //src/Pipelines.Sockets.Unofficial/Internal/Throw.cs:line 59 at Pipelines.Sockets.Unofficial.SocketAwaitableEventArgs.GetResult() in //src/Pipelines.Sockets.Unofficial/SocketAwaitableEventArgs.cs:line 74 at Pipelines.Sockets.Unofficial.SocketConnection.d81.MoveNext() in //src/Pipelines.Sockets.Unofficial/SocketConnection.Send.cs:line 64 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.IO.Pipelines.PipeCompletion.ThrowLatchedException() at System.IO.Pipelines.Pipe.GetFlushResult(FlushResult& result) at System.IO.Pipelines.Pipe.PrepareFlush(CompletionData& completionData, ValueTask`1& result, CancellationToken cancellationToken) at System.IO.Pipelines.Pipe.FlushAsync(CancellationToken cancellationToken) at System.IO.Pipelines.Pipe.DefaultPipeWriter.FlushAsync(CancellationToken cancellationToken) at Pipelines.Sockets.Unofficial.SocketConnection.WrappedWriter.FlushAsync(CancellationToken cancellationToken) in //src/Pipelines.Sockets.Unofficial/SocketConnection.cs:line 432 at StackExchange.Redis.PhysicalConnection.FlushAsync() in /_/src/StackExchange.Redis/PhysicalConnection.cs:line 286 at StackExchange.Redis.ServerEndPoint.d_120.MoveNext() in //src/StackExchange.Redis/ServerEndPoint.cs:line 885 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at StackExchange.Redis.ServerEndPoint.d97.MoveNext() in //src/StackExchange.Redis/ServerEndPoint.cs:line 566 --- End of inner exception stack trace --- --- End of inner exception stack trace --- at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor`1 processor, ServerEndPoint server) in //src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2863 at StackExchange.Redis.RedisBase.ExecuteSync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server) in //src/StackExchange.Redis/RedisBase.cs:line 54 at StackExchange.Redis.RedisDatabase.StringGet(RedisKey key, CommandFlags flags) in //src/StackExchange.Redis/RedisDatabase.cs:line 2433 at CommonUtils.RedisWrapper.StringGet(String key, String prefix) in

gurc4n commented 2 years ago

This is the exceptions in the server:

[51188] 10 Feb 14:23:48.685 # Error registering fd event for the new client: No error (conn: fd=15163) [51188] 10 Feb 14:23:49.063 # Error registering fd event for the new client: No error (conn: fd=15163) [51188] 10 Feb 14:23:49.693 # Error registering fd event for the new client: No error (conn: fd=15163) [51188] 10 Feb 14:23:50.695 # Error registering fd event for the new client: No error (conn: fd=15163) [51188] 10 Feb 14:23:51.707 # Error registering fd event for the new client: No error (conn: fd=15163) [51188] 10 Feb 14:23:52.722 # Error registering fd event for the new client: No error (conn: fd=15163) [51188] 10 Feb 14:23:53.723 # Error registering fd event for the new client: No error (conn: fd=15163)

NickCraver commented 2 years ago

It looks like you're legitimately losing the connection to the server for some reason. The backlog/retry case is something we're working on for the v2.5 release (see #1912) - you can grab the release off the MyGet feed today or the hope is it'll be on NuGet in the next few weeks as stable. It would handle commands attempting to be issued and backlog them while reconnecting (still timing out if it takes a long time) then flush them over and complete. For your situation, this should be very helpful :)

gurc4n commented 2 years ago

I will give it a try, thank you very much.

By the way, is this normal? I have 19 clients but 3263 connections. I don't do any connection recovery kind of action. ConnectionMultiplexer and IDatabase are shared objects in my code.

image

NickCraver commented 2 years ago

@gurc4n what am I looking at? Assume I know nothing about these counters (because I don't!) - is this from the server's point of view? A total counter of connections ever? If so, across what time period? Everything you can tell me about them helps me say if it's normal...without context: no idea :)

gurc4n commented 2 years ago

I am using Another Redis Desktop Manager as a Redis GUI. https://github.com/qishibo/AnotherRedisDesktopManager It looks like it is the info stats command. Is this normal to have that much of connections from 25 clients?

info stats

Stats

total_connections_received:3213 total_commands_processed:5088420 instantaneous_ops_per_sec:194 total_net_input_bytes:1279166441 total_net_output_bytes:33964510848 instantaneous_input_kbps:9.16 instantaneous_output_kbps:5803.59 rejected_connections:0 sync_full:0 sync_partial_ok:0 sync_partial_err:0 expired_keys:0 expired_stale_perc:0.00 expired_time_cap_reached_count:0 expire_cycle_cpu_milliseconds:1 evicted_keys:0 keyspace_hits:3235879 keyspace_misses:1674003 pubsub_channels:1 pubsub_patterns:0 latest_fork_usec:15629 total_forks:0 migrate_cached_sockets:0 slave_expires_tracked_keys:0 active_defrag_hits:0 active_defrag_misses:0 active_defrag_key_hits:0 active_defrag_key_misses:0 tracking_total_keys:0 tracking_total_items:0 tracking_total_prefixes:0 unexpected_error_replies:0 total_error_replies:41 dump_payload_sanitizations:0 total_reads_processed:5088401 total_writes_processed:5252906 io_threaded_reads_processed:0 io_threaded_writes_processed:0

gurc4n commented 2 years ago

The period is about 2-3 hours :) I forgot to mention it. I am wondering if I do so many calls or something wrong in the calls and getting the server to a freeze or something like that?

NickCraver commented 2 years ago

@gurc4n Those state are since the instance was restarted. Do those numbers look reasonable? Yeah sure, I guess - it's highly contextual. How many builds have happened, how many instances, how many multiplexers, etc.

For what it's worth, what you may want is info clients which shows current connections.

gurc4n commented 2 years ago

Thanks Nick, it looks like I had an unstable port of Redis. The library is good, connection count is good. Sorry for the interruption.

NickCraver commented 2 years ago

@gurc4n Glad you got it figured! I appreciate the update :)