Aspnetcore: SignalR sends incomplete JSON in socket frames when using new System.Text.Json Serializer

[BrennanConroy]

_From @suedama1756 on Tuesday, September 3, 2019 5:02:57 PM_

3.0.100-preview8-013656

SignalR JS Client: 3.0.0-preview6.19307.2

We have an issue where SignalR is sending incomplete JSON in a socket frame to the browser which results in an error in the signalr client.

 if (input[input.length - 1] !== TextMessageFormat.RecordSeparator) {
            throw new Error("Message is incomplete.");
   }

The issue does not occur when using the NewtonSoft JSON serializer. It looks like the JSON buffer is not being flushed correctly

_Copied from original issue: dotnet/corefx#40770_

[suedama1756]

To be clear, this only occurs when using the System.Text.Json serializer.

[BrennanConroy]

Do you have a sample app that we can reproduce this behavior with? Have you changed the default serializer options?

[suedama1756]

I don't have an isolated sample although it may be possible to put one together. The configuration is pretty much the default new aspnet project template in VS2019.

 if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }
            else
            {
                app.UseHsts();
            }

            app.UseRouting();
            app.UseHttpsRedirection();

            app.UseCors(options =>
            {
                options
                .AllowAnyMethod()
                .AllowAnyHeader()
                .AllowCredentials()
                .SetIsOriginAllowed(host => true);

            });

            app.UseEndpoints(routes =>
            {
                routes.MapControllers();
                routes.MapHub<ViewServerHub>("/viewport");
            });

We are using a hub with a stream configured using an unbounded Channel Reader

[BrennanConroy]

Could you provide the method(s) in ViewServerHub that you're observing the issue with? And would it be possible to grab logs and or network traces of the partial message? https://docs.microsoft.com/en-us/aspnet/core/signalr/diagnostics?view=aspnetcore-2.2

[suedama1756]

OK, I've tracked down the issue and as is always the way with these things its not where I thought it would be. The issue is failure to serialize some double values (Infinite, NaN). I put in a custom double converter quickly and this seemed to resolve the issue. Interesting I could not replicate the exact issue even with a cut down example, instead I get a "Invocation canceled due to the underlying connection being closed."

I would have expected a serialization error in the observable, or something that would help me identify the failure. I certainly wouldn't expect partial frames... Is there a way for us to make this capture any serialization errors and report those to the client?

[BrennanConroy]

Unfortunately due to the way we write messages there is no way to send a valid message to the client on serialization errors. You should see a server-side log at the Debug level with the exception that caused the client to disconnect.

When you saw the partial frames were you running the app through the debugger? Normally the connection should close immediately, but if a debugger is attached the connection will not be cleaned up in order to make dev work easier.

[halter73]

Maybe we should make this a ~warning~ error log since this is indicative of a bug in an app. We want to make sure we don't log it so severely if it's client-controlled.

[GSPP]

I understand the response is being streamed so that errors have nowhere to go. Would response buffer help? Classic ASP.NET buffers responses by default and replaces them entirely in case of error.

[halter73]

Normal response buffering (where the entire response body is buffered prior to writing) wouldn't work for SignalR since it relies on response streaming. That does work reasonably well for catching and reporting MVC response serialization errors though.

We could consider serializing each frame into a buffer prior to writing it. We would probably want to make it opt-in in order to not degrade perf. I'm not sure how many people will opt-in until after it's too late though 😞

[suedama1756]

I think the suggestion of moving the log level to warning makes a lot of sense. As soon as I enabled debug logging I tracked the issue quickly.

I can't see why response buffering wouldn't technically work as it would be fairly trivial to write the JSON in memory (potentially backed by disk for large objects) before sending it down the socket. I agree though that this doesn't feel like the correct option. Technically, this could be simulated very easily with existing infrastructure by serializing the object to JSON before writing it to the Channel and then wrapping it in a JSONWrapper struct before sending it to the channel. A CustonConverter could then be used to write raw the unwrapped JSON (although not sure the new System.Text.Json supports raw, I think I looked into this already for supported the proposed n suffix for bigint).

Another option would be to support streaming a single message across multiple frames (streaming json) in the front end. This would allow for additional messages to be injected between frames to indicate error, e.g. first frame contains partial json, next frame contains a header indicated an error. Potentially a JSON (2) protocol?

I haven't thought any of this through in any detail, just putting some ideas out there :) Clearly the other option is to test my code better!!

Thanks all, I appreciate the fast response on this

[ahsonkhan]

The issue is failure to serialize some double values (Infinite, NaN). I put in a custom double converter quickly and this seemed to resolve the issue.

@suedama1756, can you expand a bit on this? What's your input object that you are serializing and where do you end up seeing these unsupported double values that caused you to write a custom converter? I am interested in learning about that scenario, and if you could share an isolated sample (specific to the serializer itself, including the converter), that would be helpful to me (particularly because I don't think the serializer should be writing NaN/Infinity on .NET Core).

[willdean]

Maybe we should make this a warning log since this is indicative of a bug in an app. We want to make sure we don't log it so severely if it's client-controlled.

Could it be Error rather than Warning? If it wasn't for the business about it being too late to throw an exception by the time the message is serialised, this sort of serialisation problem would normally throw an exception, which would generally be logged as Error rather than anything lower.

[anurse]

Let's make it an Error log and see how that goes :). It's a terminal case and unexpected by users. If necessary we can add a config setting.

[davidfowl]

It may be reasonable to have a flag to allow buffering messages (off by default), but it would help catch issues like this

[halter73]

I know in the past, MVC has had similar issues with JsonResults. Do we have a supported way to buffer those other than using the Microsoft.AspNetCore.Buffering 0.2.2 NuGet package?

The big difference is that in MVC's case, serialization failures mean not being able to write a 500 response or diagnostic error page, while in SignalR, serialization failures cause entire connections to close.

I think that's more reason not to have a buffering option in SignalR though. Buffering in MVC could make diagnostics easier. Turning buffering on in SignalR is basically asking to swallow exceptions, drop messages, and continue. This could lead to issues in the app logic that are worse than just dropping the connection.

[davidfowl]

I think that's more reason not to have a buffering option in SignalR though. Buffering in MVC could make diagnostics easier. Turning buffering on in SignalR is basically asking to swallow exceptions, drop messages, and continue. This could lead to issues in the app logic that are worse than just dropping the connection.

Today we write directly to the connection which can result in partial messages that corrupt the payload. Buffering would fail before messages are written to the connection resulting in a server side failure without breaking the connection.

[anurse]

Or even fail the connection properly, with a message (properly sanitized for security). What happens now is an ungraceful disconnect since we can’t write a close frame.

[willdean]

As someone who suffered through debugging one of these "SignalR connection occasionally drops because the new serializer doesn't like something I said" problems, I'd ask that the API (at least in debug mode or Development environment) follows the principle of least surprise. i.e. if you pass some data into an API which it can't cope with, it throws an exception at that point.

I do get it that, in normal operation, there's an optimization which prevents this working like this, but in general, dropping the connection feels entirely unexpected, and the fact that it does it without telling the API caller that it's done it just seems plain wrong.

Rather than change the architecture (buffering, etc), could the dev-mode code just perform a test serialisation of the data at the time of the call and discard the result? That way any serialisation exceptions would automatically throw back to the caller.

[davidfowl]

Rather than change the architecture (buffering, etc), could the dev-mode code just perform a test serialisation of the data at the time of the call and discard the result? That way any serialisation exceptions would automatically throw back to the caller.

That's the same as buffering.

Reopening this for re-consideration as a "mode".

[halter73]

I'm fine with it, as long as the error closes the connection with a clear error message. I don't want some VBesque "On Error Resume Next" behavior.