RPC freezes when intensively calling delegates with WatsonTCP

[sancheolz]

Describe the bug
After updating WatsonTCP to revision 9c27fc97fb4195f21ef2044f53ada9f3323731e0, part of the RPC began to hang with infinite SendTimeout and frequent RPCs. If I replace the channel with WebSocketClientChannel, then no RPC hangs.
Send waits on server side in WatsonTcpServer.cs at
await client.WriteLock.WaitAsync(token).ConfigureAwait(false);
It's a deadlock. This seems to happen when processing RPC with intensive delegate calls, which leads to frequent sending of data from the server. As a result, many tasks are hanging on wait, but they do not continue due to thread pool exhaustion.

Expected behavior
RPCs don't hang.

Additional notes
WatsonTCP creates a lot of problems, and is also not actively supported by the developer. Maybe we should leave WebSocketClientChannel as the main one? And maybe you should abandon WatsonTCP?

[yallie]

There's a difference somewhere, but I can't figure out where.

The only difference I see that this piece of code is missing:

if (bytesCount == 0)
   break;

Your version stops if ReadAsync didn't read anything, but WatsonTcp's current version keeps on trying.

[sancheolz]

Maybe the reason of data lost in this condition. I will check my tests again with both patches. Why did you close the issue?

[yallie]

Why did you close the issue?

Sorry, looks like I missed the button! Didn't mean to.

[sancheolz]

I rolled back WatsonTCP to version 6.0.6 and applied my fix, but the problem still remained. Here is the stack of a hung call from my project(part of the code is hidden), RPC is called in the GUI:

Thread (0x83B5B):
CPU_TIME
System.Private.CoreLib!System.Threading.ManualResetEventSlim.Wait(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib!System.Threading.Tasks.Task.SpinThenBlockingWait(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib!System.Threading.Tasks.Task.InternalWaitCore(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib!System.Threading.Tasks.Task.Wait(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib!System.Threading.Tasks.Task.Wait(int32)
CoreRemoting!CoreRemoting.ServiceProxy`1[System.__Canon].Intercept(class Castle.DynamicProxy.IInvocation)
Castle.Core!Castle.DynamicProxy.AbstractInvocation.Proceed()
...User code
...User code
...User code
...User code
?!?
System.Private.CoreLib!System.Reflection.RuntimeMethodInfo.Invoke(class System.Object,value class System.Reflection.BindingFlags,class System.Reflection.Binder,class System.Object[],class System.Globalization.CultureInfo)
System.Private.CoreLib!System.Delegate.DynamicInvokeImpl(class System.Object[])
System.Windows.Forms!System.Windows.Forms.XplatUIDriverSupport.ExecutionCallback(class System.Windows.Forms.AsyncMethodData)
System.Windows.Forms!System.Windows.Forms.XplatUIDriverSupport.ExecutionCallbackInContext(class System.Object)
System.Private.CoreLib!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
System.Windows.Forms!System.Windows.Forms.XplatUIDriverSupport.ExecuteClientMessage(value class System.Runtime.InteropServices.GCHandle)
System.Windows.Forms!System.Windows.Forms.XplatUIX11.GetMessage(class System.Object,value class System.Windows.Forms.MSG&,int,int32,int32)
System.Windows.Forms!System.Windows.Forms.Application.RunLoop(bool,class System.Windows.Forms.ApplicationContext)
System.Windows.Forms!System.Windows.Forms.Application.Run(class System.Windows.Forms.ApplicationContext)
System.Windows.Forms!System.Windows.Forms.Application.Run(class System.Windows.Forms.Form)
...Main(class System.String[])

Perhaps there is a problem with the context. For myself, I've already switched to WebSocket.

P.S. The latest revision of CoreRemoting works perfectly, thanks for this project.

[sancheolz]

Probably the last failed test https://github.com/theRainbird/CoreRemoting/actions/runs/15205383494/job/42767178601?pr=178 related to this issue.

[sancheolz]

I thought there were problems with asynchrony and added AsyncLock SendLock before sending on the client and server like in Websocket channel, but it didn't help. Perhaps tcpdump or the addition of logs for sending and receiving data will reveal the secret. Even in WatsonTcp, empty catch blocks at receive were noticed. Maybe something is hiding there.

[sancheolz]

Send waits on server side in WatsonTcpServer.cs at
await client.WriteLock.WaitAsync(token).ConfigureAwait(false);
It's a deadlock.

[sancheolz]

This seems to happen when processing RPC with intensive delegate calls, which leads to frequent sending of data from the server. As a result, many tasks are hanging on wait, but they do not continue due to thread pool exhaustion.

[yallie]

await client.WriteLock.WaitAsync(token).ConfigureAwait(false);
It's a deadlock.

Why do you believe it's a deadlock?

Is there another logical thread holding the lock while waiting for this blocked call to finish?

many tasks are hanging on wait, but they do not continue due to thread pool exhaustion.

Some time ago I added a custom thread pool for the server-side broadcasts to tackle with potential global thread pool starvation. SimpleLockThreadPool is configurable (can specify concurrency level and max work item queue size), so server-size invocations shouldn't affect the thread pool.

WatsonTCP creates a lot of problems, and is also not actively supported by the developer. Maybe we should leave WebSocketClientChannel as the main one? And maybe you should abandon WatsonTCP?

I agree that it shouldn't be the default one, but we should probably keep it as a separate library for backwards compatibility for the time being.

[sancheolz]

Maybe it's not a deadlock, but it just looks like it. WriteLock is SemaphoreSlim. And it does not act as a queue and does not give priority to pending tasks. One of the tasks is on hold, but is not being completed due to many other incoming tasks. If I put queue before sending in tcp channel, then maybe the problem will go away. I'll check it out next week.

[sancheolz]

Why do you believe it's a deadlock?

WatsonTCP was modified like this:

--- /tmp/3SkSqK_WatsonTcpServer.cs
+++ /tmp/TRwZfK_WatsonTcpServer.cs
@@ -1234,6 +1236,8 @@
 
         private async Task<bool> SendInternalAsync(ClientMetadata client, WatsonMessage msg, long contentLength, Stream stream, CancellationToken token)
         {
+            Console.WriteLine($"Begin Send msg {msg} {client == null} {msg == null}");
             if (client == null) throw new ArgumentNullException(nameof(client));
             if (msg == null) throw new ArgumentNullException(nameof(msg));
 
@@ -1241,6 +1245,7 @@
             {
                 if (stream == null || !stream.CanRead)
                 {
+                    Console.WriteLine($"stream == null || !stream.CanRead {msg}");
                     throw new ArgumentException("Cannot read from supplied stream.");
                 }
             }
@@ -1250,28 +1255,36 @@
                 CancellationTokenSource linkedCts = CancellationTokenSource.CreateLinkedTokenSource(token, _Token);
                 token = linkedCts.Token;
             }
-
-            await client.WriteLock.WaitAsync(token).ConfigureAwait(false);
-
+            Console.WriteLine($"WriteLock acquire {msg}");
             try
             {
+
+                await client.WriteLock.WaitAsync(token).ConfigureAwait(false);
+
+
+                Console.WriteLine($"Send msg header {msg}");
                 await SendHeadersAsync(client, msg, token).ConfigureAwait(false);
+                Console.WriteLine($"Send msg {msg}");
                 await SendDataStreamAsync(client, contentLength, stream, token).ConfigureAwait(false);
 
                 _Statistics.IncrementSentMessages();
                 _Statistics.AddSentBytes(contentLength);
+                Console.WriteLine($"Sended msg {msg}");
                 return true;
             }
-            catch (TaskCanceledException)
-            {
+            catch (TaskCanceledException e)
+            {
+                Console.WriteLine($"TaskCanceledException msg {msg} {Logger.ExceptionToString(e)}");
                 return false;
             }
-            catch (OperationCanceledException)
-            {
+            catch (OperationCanceledException e)
+            {
+                Console.WriteLine($"OperationCanceledException msg {msg} {Logger.ExceptionToString(e)}");
                 return false;
             }
             catch (Exception e)
             {
+                Console.WriteLine($"Exception msg {msg} {Logger.ExceptionToString(e)}");
                 _Settings.Logger?.Invoke(Severity.Error, _Header + "failed to write message to " + client.ToString() + ": " + e.Message);
                 _Events.HandleExceptionEncountered(this, new ExceptionEventArgs(e));
                 return false;

And the last message written to the console was "WriteLock acquire ...". After that, no exceptions were displayed in the console.