SignalR client library needs better logging/access to underlying message data

[MaximG1234]

Is there an existing issue for this?

• [X] I have searched the existing issues

Is your feature request related to a problem? Please describe the problem.

I made a silly mistake today that took me some time to debug because there appears to be no easy way to access the underlying messages sent by SignalR as plaintext.

I have a method where I added a cancellationTokenSource as such.

using (var cancelToken = new CancellationTokenSource(timeoutMS))
{
     return clientProxy.InvokeAsync<T>(methodName, request, cancelToken);
}

You might already be able to spot the problem (cancelToken should be cancelToken.Token) I had forgotten about this simple change I made and suddenly started getting the error:

Error reading JSON. '{' is invalid after a value. Expected either ',', '}', or ']'. LineNumber: 0 | BytePositionInLine: 98.

I tried to enable detailed logging by adding trace for logging messages.

var conn = new HubConnectionBuilder()
.ConfigureLogging(logging =>
{
    logging.SetMinimumLevel(LogLevel.Trace);
});

Yet unfortunately I received no further details other than the message above.

In the end I needed to implement my own custom IHubProtocol by duplicating JsonHubProtocol which finally revealed the real error to me which was:

{"type":1,"invocationId":"9","target":"blahblah","arguments":[{blahblah}{"type":7,"error":"Connection closed with an error. NotSupportedException: Serialization and deserialization of 'System.IntPtr' instances are not supported. Path: $.Token.WaitHandle.Handle.","allowReconnect":true}

Describe the solution you'd like

I believe inside JsonHubProtocol -> ParseMessage on the error condition the entire message payload should be shown to the user or at least if tracing is turned on this should be the behaviour.

It should not be this difficult to find out what happened to cause deserialisation to fail.

Additional context

In summary, there should be more information when an error condition occurs deep inside the protocol.

[davidfowl]

var conn = new HubConnectionBuilder()
.ConfigureLogging(logging =>
{
    logging.SetMinimumLevel(LogLevel.Trace);
});

What logger provider did you enable?

[MaximG1234]

Hey @davidfowl,

Uggh, so I did make a mistake there because I was already receiving a message I thought I had provided a provider but just for curiosity sake, I have gone back and enabled it properly but the error message still wouldnt have helped me and is basically identical to the message I showed above.

Realistically I still would have no idea of what actually went wrong without recreating the steps above I described.

fail: Microsoft.AspNetCore.SignalR.Client.HubConnection[69]
      HubConnection reconnecting due to an error.
      System.IO.InvalidDataException: Error reading JSON.
       ---> System.Text.Json.JsonReaderException: '{' is invalid after a value. Expected either ',', '}', or ']'. LineNumber: 0 | BytePositionInLine: 98.
         at System.Text.Json.ThrowHelper.ThrowJsonReaderException(Utf8JsonReader& json, ExceptionResource resource, Byte nextByte, ReadOnlySpan`1 bytes)
         at System.Text.Json.Utf8JsonReader.ConsumeNextToken(Byte marker)
         at System.Text.Json.Utf8JsonReader.ConsumeNextTokenOrRollback(Byte marker)
         at System.Text.Json.Utf8JsonReader.ReadSingleSegment()
         at System.Text.Json.Utf8JsonReader.Read()
         ......
         at Microsoft.AspNetCore.SignalR.Client.HubConnection.ReceiveLoop(ConnectionState connectionState)
trce: Microsoft.AspNetCore.SignalR.Client.HubConnection[72]
      Reconnect attempt number 1 will start in 00:00:05.
[trce: Microsoft.AspNetCore.SignalR.Client.HubConnection[20]
      Releasing Connection Lock in HandleConnectionClose (/_/src/SignalR/clients/csharp/Client.Core/src/HubConnection.cs:1396).
15:38:05 WRN] Connection reconnecting after error in HubConnectionManager with error Error reading JSON.
'{' is invalid after a value. Expected either ',', '}', or ']'. LineNumber: 0 | BytePositionInLine: 98.

PS: Thank you for all your hard work on SignalR @davidfowl absolutely love using it.

[BrennanConroy]

I'm a bit confused here, the logs from your recent comment seem to indicate an error parsing on the client side, but the original issue shows that there was an error parsing on the server side.

If you test the original problem with logging turned on (now that you fixed the logging 😄) you should see the error "Connection closed with an error. NotSupportedException: Serialization and deserialization of 'System.IntPtr' instances are not supported. Path: $.Token.WaitHandle.Handle." that you showed in your original issue. Additionally, that error would be propagated to the reconnect or close handler registered on your client.

Regarding your new comment showing an error from the client side, that log isn't great and could probably be improved. What did you do to cause that error so we can repro?

[ghost]

Hi @MaximG1234. We have added the "Needs: Author Feedback" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time.

[MaximG1234]

Hi @BrennanConroy,

Yep apologies, its probably a bit confusing because I am using the latest version of SignalR which supports reverse invocation from Server -> Client.

In my case the method above:

using (var cancelToken = new CancellationTokenSource(timeoutMS))
{
     return clientProxy.InvokeAsync<T>(methodName, request, cancelToken);
}

Is being invoked from the ASP.NET Core application and being sent to a .NET 7 console client utilising Microsoft.AspNetCore.SignalR.Client Version 7.0.0-preview.7.22376.6.

As you correctly note interestingly the error is being generated on the client (in this case the .NET 7 console app) rather than the server.

Reproducing this issue would simply involve invoking a client from the ASP.NET Core app to any method on the client with the parameters as specified.

Does this make sense?

[MaximG1234]

PS: I note that I did not appear to receive an error on the ASP.NET Core application but I have a relatively complicated process that I am using to make my invocations which might have tripped things up.

Also while I am using EnableDetailedErrors on the ASP.NET side I have not configured the logging filters which probably would have provided me more information.

The fact that the error was appearing on the client tripped me up and made me 'ignore' the server thinking the error occured on the client and wasnt related to the server.

I guess my general point is that it shouldnt be this easy to shoot yourself in the foot under the circumstances I described, in an ideal world both the server would generate an error (which it might have as you described) AND the client would be able to parse the message correctly and output something meaningful, or if it truly cant then just print the entire message.

[MaximG1234]

Additionally, that error would be propagated to the reconnect or close handler registered on your client.

100% this is not happening if you take a look at the error I've received (which was also the one pushed to the reconnect handler, the json parser is failing to parse the message. I didn't delve very deeply but I suspect that 'NotSupportedException:' or 'Path:' or similar is tripping it up. After thinking about it more, I would definitely argue that this is borderline a bug.

[BrennanConroy]

Looking at this more closely, you're hitting the issue described in https://github.com/dotnet/aspnetcore/issues/13651#issuecomment-527625710. As noted in the comment, there is a log on the server side that will have the nicer Json error message (it's Error level now) that would have pointed you to the issue.

[ghost]

Thanks for contacting us.

We're moving this issue to the .NET 8 Planning milestone for future evaluation / consideration. We would like to keep this around to collect more feedback, which can help us with prioritizing this work. We will re-evaluate this issue, during our next planning meeting(s). If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[rafikiassumani-msft]

Triage: We should do the same thing we do in the JS client and log the raw messages.

https://github.com/dotnet/aspnetcore/blob/c647f58bd0e53ec5cd13bdec037ac53c444abf99/src/SignalR/clients/ts/signalr/src/IHttpConnectionOptions.ts#L39 https://github.com/dotnet/aspnetcore/blob/c647f58bd0e53ec5cd13bdec037ac53c444abf99/src/SignalR/clients/ts/signalr/src/Utils.ts#L61