StackExchange / StackExchange.Redis

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

BUG -> PhysicalConnection System.NullReferenceException: #2576

Closed DeepWorksStudios closed 6 months ago

DeepWorksStudios commented 9 months ago

Under high load of my development environment the StackExchange.Redis PhysicalConnection class on internal void WriteHeader causes a uncaught exception without any clue. I am using the latest redis release on Ubuntu and the latest nuget version of stackexchange redis

Line 832 -> var span = _ioPipe!.Output.GetSpan(commandBytes.Length + 8 + Format.MaxInt32TextLen + Format.MaxInt32TextLen);

It seems like for no explainable reason the variable _ioPipe is null which causes the exception

**Exception data ↓↓**   | Name | Value | Type -- | -- | -- | -- ◢ | $exception | {"Object reference not set to an instance of an object."} | System.NullReferenceException   | ▶ Data | {System.Collections.ListDictionaryInternal} | System.Collections.IDictionary {System.Collections.ListDictionaryInternal}   | HResult | -2147467261 | int   | HasBeenThrown | true | bool   | HelpLink | null | string   | ▶ InnerException | null | System.Exception   | Message | "Object reference not set to an instance of an object." | string   | SerializationStackTraceString | " at StackExchange.Redis.PhysicalConnection.WriteHeader(RedisCommand command, Int32 arguments, CommandBytes commandBytes) in /_/src/StackExchange.Redis/PhysicalConnection.cs:line 809" | string   | SerializationWatsonBuckets | null | object   | Source | "StackExchange.Redis" | string   | StackTrace | " at StackExchange.Redis.PhysicalConnection.WriteHeader(RedisCommand command, Int32 arguments, CommandBytes commandBytes) in /_/src/StackExchange.Redis/PhysicalConnection.cs:line 832" | string   | ▶ TargetSite | {Void WriteHeader(StackExchange.Redis.RedisCommand, Int32, StackExchange.Redis.CommandBytes)} | System.Reflection.MethodBase {System.Reflection.RuntimeMethodInfo}   | _HResult | -2147467261 | int   | ▶ _data | {System.Collections.ListDictionaryInternal} | System.Collections.IDictionary {System.Collections.ListDictionaryInternal}   | _dynamicMethods | null | object[]   | _exceptionMethod | null | System.Reflection.MethodBase   | _helpURL | null | string   | ▶ _innerException | null | System.Exception   | _ipForWatsonBuckets | 0x00007ffa328be781 | System.UIntPtr   | _message | "Object reference not set to an instance of an object." | string   | _remoteStackTraceString | null | string   | _source | null | string   | ▶ _stackTrace | {sbyte[48]} | byte[] {sbyte[]}   | _stackTraceString | null | string   | _watsonBuckets | null | byte[]   | _xcode | -532462766 | int   | _xptrs | 0x0000000000000000 | System.IntPtr   | ▶ Static members |   |  

Callstack data ↓↓

StackExchange.Redis.dll!StackExchange.Redis.PhysicalConnection.WriteHeader(StackExchange.Redis.RedisCommand command, int arguments, StackExchange.Redis.CommandBytes commandBytes) Line 832 C#
StackExchange.Redis.dll!StackExchange.Redis.Message.CommandValueValueMessage.WriteImpl(StackExchange.Redis.PhysicalConnection physical) Line 1503   C#
StackExchange.Redis.dll!StackExchange.Redis.Message.WriteTo(StackExchange.Redis.PhysicalConnection physical) Line 699   C#
StackExchange.Redis.dll!StackExchange.Redis.PhysicalBridge.WriteMessageToServerInsideWriteLock(StackExchange.Redis.PhysicalConnection connection, StackExchange.Redis.Message message) Line 1508    C#
StackExchange.Redis.dll!StackExchange.Redis.PhysicalBridge.WriteMessageInsideLock(StackExchange.Redis.PhysicalConnection physical, StackExchange.Redis.Message message) Line 713    C#
StackExchange.Redis.dll!StackExchange.Redis.PhysicalBridge.WriteMessageTakingWriteLockAsync_Awaited(System.Threading.Tasks.Task<bool> pending, StackExchange.Redis.PhysicalConnection physical, StackExchange.Redis.Message message) Line 1277  C#
[Resuming Async Method] 
System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<StackExchange.Redis.WriteResult>.AsyncStateMachineBox<StackExchange.Redis.PhysicalBridge.<WriteMessageTakingWriteLockAsync_Awaited>d__106>.ExecutionContextCallback(object s) Line 287    C#
System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 183  C#
System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<StackExchange.Redis.WriteResult>.AsyncStateMachineBox<StackExchange.Redis.PhysicalBridge.<WriteMessageTakingWriteLockAsync_Awaited>d__106>.MoveNext(System.Threading.Thread threadPoolThread) Line 324    C#
System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<StackExchange.Redis.WriteResult>.AsyncStateMachineBox<StackExchange.Redis.PhysicalBridge.<WriteMessageTakingWriteLockAsync_Awaited>d__106>.MoveNext() Line 302    C#
System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 301   C#
System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.System.Threading.IThreadPoolWorkItem.Execute() Line 647 C#
System.Private.CoreLib.dll!System.Threading.ThreadPoolWorkQueue.Dispatch() Line 924 C#
System.Private.CoreLib.dll!System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() Line 77 C#
[Async Call Stack]  
[Async] StackExchange.Redis.dll!StackExchange.Redis.ServerEndPoint.WriteDirectOrQueueFireAndForgetAsync.__Awaited|131_0<bool>(System.Threading.Tasks.ValueTask<StackExchange.Redis.WriteResult> l_result) Line 848  C#
[Async] StackExchange.Redis.dll!StackExchange.Redis.ServerEndPoint.HandshakeAsync(StackExchange.Redis.PhysicalConnection connection, StackExchange.Redis.LogProxy log) Line 930 C#
DeepWorksStudios commented 9 months ago

@NickCraver Could you try to reproduce it. The case would be on windows install Ubuntu via wsl2 and run there redis and run a test web api that try to establish a connection to the redis client while running the web api than try to increase the cpu load via as exsample windows defender full anti virus scan than the load will be 90 till 100% and than always this is the result

DeepWorksStudios commented 8 months ago

Since i updated to .net 8 i need to remove redis completly since now nothing works anymore not even under normal load

"StackExchange.Redis.RedisTimeoutException: 'Timeout performing UNSUBSCRIBE (10ms), inst: 1, qu: 0, qs: 0, aw: False, bw: Inactive, rs: ReadAsync, ws: Idle, in: 0, in-pipe: 0, out-pipe: 0, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 4, serverEndpoint: 127.0.0.1:6379, conn-sec: 2,76, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: DESKTOP-NO01VLO(SE.Redis-v2.6.122.38350), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=12,Max=32767), POOL: (Threads=6,QueuedItems=0,CompletedItems=312,Timers=7), v: 2.6.122.38350 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)'"

mgravell commented 8 months ago

@DeepWorksStudios I am very interested, from both a "redis library" aspect and from a "I'm a small part of the .NET 8 team" aspect. So: is there any more context you can give me here about what you saw? What kind of application this was, for example? If it was ASP.NET then I'm even more intrigued, and I can carve out dedicated work time to try and investigate, but other environments: still very much of interest.

DeepWorksStudios commented 8 months ago

image

It's an ASP.Net Core Web API: On.net 7, it just happens under load; in.net 8, different problems arise, and basically, it's not functional at all

I'm using SignalR Redis (AddStackExchangeRedisCache) And distribute memory (AddStackExchangeRedisCache). As well, I implemented a self created RedisHelthCheck

@mgravell

DeepWorksStudios commented 6 months ago

Any updates?

jlao commented 6 months ago

I'm not sure if it's exactly the same, but I saw this in logs when we had a network outage due to a network switch getting rebooted.

We have logs hooked up to the mux callbacks:

ConnectionFailed: SocketFailure (ReadSocketError/TimedOut, last-recv: 413) on 10.10.70.233:6001/Interactive, Flushed/Faulted, last: GET, origin: ReadFromPipe, outstanding: 2, last-read: 23s ago, last-write: 18s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 9 of 10 available, in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.6.104.40210

ConnectionFailed: SocketFailure (ReadSocketError/TimedOut, last-recv: 770) on 10.10.70.231:6001/Interactive, Flushed/Faulted, last: GET, origin: ReadFromPipe, outstanding: 2, last-read: 23s ago, last-write: 18s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 9 of 10 available, in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.6.104.40210

InternalError: System.NullReferenceException: Object reference not set to an instance of an object.
       at StackExchange.Redis.PhysicalConnection.WriteHeader(RedisCommand command, Int32 arguments, CommandBytes commandBytes) in /_/src/StackExchange.Redis/PhysicalConnection.cs:line 809
       at StackExchange.Redis.RedisTransaction.TransactionMessage.WriteImpl(PhysicalConnection physical) in /_/src/StackExchange.Redis/RedisTransaction.cs:line 439
       at StackExchange.Redis.Message.WriteTo(PhysicalConnection physical) in /_/src/StackExchange.Redis/Message.cs:line 706
jlao commented 6 months ago

Forgot to add that we're using version 2.6.104

NickCraver commented 6 months ago

Thanks for the report and stacks here, much appreciated :) Adding some handling for this in #2629.