Aspnetcore: Unknown disconnect happened and "ThrowInvalidOperationException_BackpressureDeadlock"

[hours10000]

coordserver.log

Describe the bug

When I send several small message from signalr client to signalr hub，sometimes will raise a disconnect event. Message package is very small: 40B more or less ， one per millisecond . The hub side do some time-consuming operations, 2 second in one message process operation。

When disconnect happened, the exception is null:2019-05-31 22:06:36,494 [6] DEBUG (null) CoordServer.Hubs.ServerHub >>> OnDisconnectedAsync Start, exception: (null)

or :2019-05-31 22:13:40,699 [23] ERROR (null) Microsoft.AspNetCore.SignalR.HubConnectionHandler >>> Error when processing requests. System.InvalidOperationException: Advancing examined to the end would cause pipe to deadlock because FlushAsync is waiting. at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException_BackpressureDeadlock() at System.IO.Pipelines.Pipe.AdvanceReader(BufferSegment consumedSegment, Int32 consumedIndex, BufferSegment examinedSegment, Int32 examinedIndex) at System.IO.Pipelines.Pipe.AdvanceReader(SequencePosition& consumed, SequencePosition& examined) at System.IO.Pipelines.Pipe.DefaultPipeReader.AdvanceTo(SequencePosition consumed, SequencePosition examined) at Microsoft.AspNetCore.SignalR.HubConnectionHandler1.DispatchMessagesAsync(HubConnectionContext connection)
at Microsoft.AspNetCore.SignalR.HubConnectionHandler1.RunHubAsync(HubConnectionContext connection).

From these links , I thought it maybe something about the size of ApplicationMaxBufferSize ,
but

Today SignalR needs to buffer the entire message before it calls your hub and it doesn't start consuming the buffer until it seems an entire message.

In my program, the message size is so small, why I still met this error？
Any helps? Thanks!

2266
8142
2322
5307

Additional context

Microsoft.AspNetCore.SignalR.Client 1.1.0
Microsoft.NETCore.App 2.2.0

[hours10000]

ChatSample.zip

Hi,
I tried with the sample in SignalR-samples,It's has the same problem。
I just add two function in this sample:

public async Task MessageBoxGetList(string resKey, W2CMsgGetListReq req) { _logger.LogInformation("MessageBoxGetList: {0}", req.account); System.Threading.Thread.Sleep(2 * 1000); }

public override Task OnDisconnectedAsync(Exception exception) { _logger.LogInformation("OnDisconnectedAsync: {0}", exception); return base.OnDisconnectedAsync(exception); }

Thanks.

ChatSample.txt

[hours10000]

Hi,
I checked the source code, the disconnect:
2019-05-31 22:06:36,494 [6] DEBUG (null) CoordServer.Hubs.ServerHub >>> OnDisconnectedAsync Start, exception: (null)
comes from RunHubAsync function(in the red part of runasync.png ),
Why the exception is null ?Maybe because the result.IsCanceled or result.IsCompleted (in the red part of dispatchMessageAsync.png).
But , my client is sending messages all the time when the server met the disconnect event.

Thanks.

[davidfowl]

How big are the messages you are sending?

[hours10000]

Thanks for your response。

How big are the messages you are sending?

About 40B, every messsage just contains a string ,like this "test:index:9-timestramp:1559313957345" .

[hours10000]

This is the definition of the message：

public interface IApiMessage { }

public class W2CMsgGetListReq : IApiMessage
{
    public string account;
}

[hours10000]

Hi , I know, the reason of the first disconnect exception:
When I modified the log level from info ->debug， I got this :
Client timeout (30021ms) elapsed without receiving a message from the client. Closing connection.
Then, I will get this exception:
DEBUG (null) CoordServer.Hubs.ServerHub >>> OnDisconnectedAsync Start, exception: (null)

This is because the Hub function "MessageBoxGetList" is a time-consuming function， the DefaultClientTimeoutInterval is 30 seconds, So If my Hub got 16 message (every message cost 2s) in one time , this exception will appear.

[hours10000]

But I still did not find out the reason why this happened:

2019-06-06 19:39:34,256 [6] ERROR (null) Microsoft.AspNetCore.SignalR.HubConnectionHandler >>> Error when processing requests. System.InvalidOperationException: Advancing examined to the end would cause pipe to deadlock because FlushAsync is waiting. at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException_BackpressureDeadlock() at System.IO.Pipelines.Pipe.AdvanceReader(BufferSegment consumedSegment, Int32 consumedIndex, BufferSegment examinedSegment, Int32 examinedIndex) at System.IO.Pipelines.Pipe.AdvanceReader(SequencePosition& consumed, SequencePosition& examined) at System.IO.Pipelines.Pipe.DefaultPipeReader.AdvanceTo(SequencePosition consumed, SequencePosition examined) at Microsoft.AspNetCore.SignalR.HubConnectionHandler1.DispatchMessagesAsync(HubConnectionContext connection)
at Microsoft.AspNetCore.SignalR.HubConnectionHandler1.RunHubAsync(HubConnectionContext connection)

I really did not send a huge message, and every message I send to Hub just in 40B more or less.

[BrennanConroy]

Took a look at this and your analysis is correct

This is because the Hub function "MessageBoxGetList" is a time-consuming function, the DefaultClientTimeoutInterval is 30 seconds, So If my Hub got 16 message (every message cost 2s) in one time , this exception will appear.

The team will discuss this and decide on whether we can do anything here.

On a side-note, it's probably not a good idea to have your client send a message every millisecond if it takes the server 2 seconds to process the message.

[anurse]

Based on the investigation I don't think we have a clear idea on how to prevent this kind of overload in 3.0. Moving to the backlog.

On a side-note, it's probably not a good idea to have your client send a message every millisecond if it takes the server 2 seconds to process the message.

@hours10000 This really is the source of the problem. If you take 2 seconds to process a message but messages are arriving consistently faster than that, you're creating an ever-growing queue. The ping timeout is a symptom of this, but I think you need some kind of batching on the client side to avoid overloading the server like this. As I said above, we do think we could do better at protecting you from this, but it's still a bit of a design problem to be sending messages much faster than you can process them.

[davidfowl]

In 3.0 the error won't happen, you'll just get throttled.

[hours10000]

Thanks for all your response about this disconnect event "OnDisconnectedAsync Start, exception: (null)"。
Yes, I have done something on my client to avoid overloading the server like this 。

[hours10000]

In 3.0 the error won't happen, you'll just get throttled.

Hi, @davidfowl
Allow me to confirm: Is your answer to this error : "Error when processing requests. System.InvalidOperationException: Advancing examined to the end would cause pipe to deadlock because FlushAsync is waiting" ?Thanks.

[davidfowl]

Allow me to confirm: Is your answer to this error : "Error when processing requests. System.InvalidOperationException: Advancing examined to the end would cause pipe to deadlock because FlushAsync is waiting" ?Thanks.

Yes, this exception has been removed completely from 3.0.

[halter73]

I will add that in 3.0, you will only get throttled if you don't advance the "examined" position. If you "examine" untrusted data that arrives without bounds (maybe you're scanning for a separator token before parsing a message for example), you've just opened yourself up to a big memory leak.

[davidfowl]

That’s not exposed to SignalR users. We also have a max message limit in SignalR itself

[anurse]

We no longer throw this error in 3.0. There is still a maximum message size, but it is configurable (and docs will be updated).