Json Serializer ReferenceLoopHandling / Truncated response / Chunked terminator behaviour

[Tratcher]

From @chrisckc on November 22, 2017 0:52

Hi,

This is a continuation of an issue that i and others have previously raised with v1.x

aspnet/IISIntegration#285

aspnet/AspNetCoreModule#26

I wanted to re-test the behaviour of this so I upgraded a test project i originally created last year to demo the issue from dotnet v1.x to v2.0.0 (i am currently using SDK v2.0.3)

Previously in dotnet1.0:

Previously in v1 when an object graph containing a circular reference was serialized, the JSON response text was truncated at the point where the circular reference would have been encountered, but the JSON was correctly closed off with the correct curly braces and square bracket. The response was also missing the Chunked Terminator and showed an error indicating such in the Chrome developer console. However the response showed a 200 OK status code caused by the fact that the response headers had already been sent before the exception was encountered (due to the response not being buffered). When i added the ResponseBuffering middleware i managed to get a 500 status code and exception to be returned.

Now in dotnet2.0:

The behaviour in version 2 is slightly different, the status code is still 200 OK due to the unbuffered response, however the truncated JSON is now properly truncated and does not have the closing braces and square bracket etc. The Chunked terminator now seems to be present as i am no longer seeing an error in the Chrome developer console. Adding the ResponseBuffering middleware still allows a 500 status code and exception as previously.

As in v1 , using v2, if i set the serializer to ignore ReferenceLoop errors then it works fine because the self referencing loop is ignored rather than followed:
o.SerializerSettings.ReferenceLoopHandling = ReferenceLoopHandling.Ignore;

I have the following 4 thoughts on this:

1. The 200 status code is misleading but unavoidable due to the unbuffered response, if ultimate performance is not an issue then use the ResponseBuffering middleware to simplify client error handling behaviour.

2. If you are using EF, depending on your model you will probably end up having to use ReferenceLoopHandling.Ignore unless you want to write code to manipulate your object graph to remove any loops.

3. The truncated JSON is now correct in that it is no longer valid JSON so should prevent incorrect / misleading data from being unknowingly received by a client, the client's JSON parser should throw an error.

4. The Chunked terminator now being present could either be a bad thing or a good thing depending on your point of view or preference. In my opinion now that the JSON is invalid the chunked terminator may as well be present so at least the response will be valid and not confuse any reverse proxy's or client libraries.

So all in all this is an improvement, however... if i use the ResponseCompression middleware it ends up back in the land of the unknown because i now get a completely empty response body with the 200 OK status code, so a client may well think there is genuinely no data available from the request it just made, and won't know there was actually an error thrown on the server.

This is a good example of why having to rely on a quirk of behaviour to detect errors is bad, the behaviour can easily be changed by configuration changes, such as adding some middleware in this example. It seems like the only way make to make the behaviour consistent is to use response buffering, so i think this should really be the default configuration for a new .NET Core WebApi project.

The ResponseCompression middleware is working correctly in normal circumstances as i can see the response in both Postman and Chrome with the header Content-Encoding: gzip

Btw. The above was tested on a Mac using the AspNetCore Kestrel server that runs when i use "dotnet run"

I have now updated the demo repo which i used originally to dotnet2.0 and added the ResponseCompression middleware:
https://github.com/chrisckc/TodoApiDemo

Copied from original issue: aspnet/AspNetCoreModule#259

[chrisckc]

@Tratcher last time i tried the Fiddler beta on may Mac i didn't work properly, i have now tried this using fiddler in my Windows VM after changing the Kestrel Listen options to use IPAddress.Any to allow access from my VM.

Using fiddler I can confirm that the Chunked terminator is indeed missing from the response, this is the case regardless of whether the ResponseCompression middleware is used. In my previous post i thought it was now there because previously when tested (last year) Chrome always reported an error in the developer console, it seems that Chrome 62 behaves differently. Again, an example of reliance on another piece of behaviour which has now changed. The only correct behaviour is to follow established standards and never return a 200 OK when an error has occurred.

Fiddler showing the missing chunked terminator:

I noticed something odd with fiddler when the ResponseCompression is enabled, it doesn't seem to be showing all of the headers, even when viewing the raw headers.
Here are the headers reported by fiddler:

Here are the headers reported by both Postman and the Chrome Network tool:

Content-Encoding →gzip
Content-Type →application/json; charset=utf-8
Date →Wed, 22 Nov 2017 10:16:06 GMT
Server →Kestrel
Transfer-Encoding →chunked
Vary →Accept-Encoding

It seems that fiddler is hiding the Content-Encoding and Vary headers. instead there is just a yellow bar saying that the response body is encoded. If i decode the response i am able to see the partial response body when ResponseCompression is enabled, using Postman or Chrome it just shows as empty.

Not everyone uses fiddler, i used to use it all the time but now i'm using macOS most of the time i use either Postman or Chrome dev tools.

The point being is that the default behaviour of a new ASP.NET Core WebApi is inconsistent with regard to errors that may occur during serialization of the response and will result in errors that are easy to miss during development and testing. I think that the ResponseBuffering middleware should be included by default.

[Tratcher]

ResponseBuffering is not in templates by default because it adds latency and memory overhead. Errors like the one you're describing primarily happen in the development environment where there are a number of tools to assist in debugging.

[chrisckc]

@Tratcher Yes it adds latency and memory overhead but at the expense of additional traffic generated due the chunking information that is added to the response. Yes there are tools, but those tools wont help anyone developing the client side of the app. Depending on the client they will either just see a network error (due to the missing terminator) or a response parsing error.

@divega @halter73 It is really useful to be able to log errors that occur during development, testing and production to a central store, however i have found that with the default .Net Core WebApi project configuration (ie. no response buffering) it is not possible to catch errors that occur during serialization using either of the 2 exception handling methods:

Using the Exception Filter method, such as:
var builder = services.AddMvc(config => config.Filters.Add(typeof(GlobalExceptionFilter)));
errors that occur during serialization are not picked up the the filter, no warning is shown in the console log and the error is just reported by Kestrel:

fail: Microsoft.AspNetCore.Server.Kestrel[13]
Connection id "0HL9IQ3CU1HDJ", Request id "0HL9IQ3CU1HDJ:00000001": An unhandled exception was thrown by the application.
Newtonsoft.Json.JsonSerializationException: Self referencing loop detected for property 'notes' with type 'System.Collections.Generic.List`1[TodoApi.Models.Note]'. Path '[0].todoItem'.

Using the ExceptionHandler method:

app.UseExceptionHandler(options => 
                options.Run(async context => await exceptionHandler.HandleException(context)));

the Exception Handler does not execute, instead, a warning shown in the console and the error is reported by kestrel:

warn: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[0]
The response has already started, the error handler will not be executed.
fail: Microsoft.AspNetCore.Server.Kestrel[13]
Connection id "0HL9IQ201C9VT", Request id "0HL9IQ201C9VT:00000001": An unhandled exception was thrown by the application.
Newtonsoft.Json.JsonSerializationException: Self referencing loop detected for property 'notes' with type 'System.Collections.Generic.List`1[TodoApi.Models.Note]'. Path '[0].todoItem'.

So it seems that unless there is a way to capture and handle the exceptions that are picked up by Kestrel there is no way to plug code into a.NET Core WebApi project to reliably log all errors to a database or error logging facility?

I also noticed that even with Response Buffering on, the Exception Filter method still does not work, however the ExceptionHandler method does work.

For errors that occur inside the controller methods, both the Filter and ExceptionHandler methods work fine, its the ones that occur outside that have the issues.

I can't find anything in the .NET Core documentation that explains in detail how the error handling works and what to watch out for, or how this differs from previous versions of .NET (non core)

This kind of issue does not exist using Node/Express with the standard template and it's error handler function. The res.send(someobject) function in Express doesn't use a stream with chunked transfer when it serializes the object, however if deliberately send a chunked response by making multiple calls to res.write(sometextcontent) and then trigger an error before res.end(), the error handler is still called. In that mode there are the same restrictions as in .Net Core, the headers have been sent so can't set the status code, but it does at least allows the error to be logged and gives much more control as i am able to do things such as determine if the headers have been sent and append error details to the partially completed response before terminating the chunked response ( res.end() ) and then closing the connection. Granted that when responding with json, the response body wont be valid, but at least someone working the client side will see some error information in the response body when debugging. Also a correctly terminated response won't cause network errors in clients or reverse proxies etc.

People coming from Node/Express or even previous versions of .NET WebApi will likely be caught out by this behaviour. It not just circular references, any error that may occur during serialization of the response object would result in this behaviour. What would happen if an error occurs while streaming out a file or some text into the response? The same thing i would expect.

The above is just my opinion, but i think it's worth consideration.

[divega]

If you are using EF, depending on your model you will probably end up having to use ReferenceLoopHandling.Ignore unless you want to write code to manipulate your object graph to remove any loops.

Just in case it helps clarify the actual scope of this issue: the correlation with EF Core or EF is only spurious. Any application that deals with the serialization of object graphs could hit the same problem.

[Infoseeker]

Is this issue resolved ?

[chrisckc]

With regards to this issue concerning how serialization errors are handled, whether the error is a Reference Loop error or some other kind of serialization error, the behaviour is still the same using SDK 2.1.105 and runtime 2.0 7

The main issues in the default configuration that does not use response buffering (instead sending the response in chunks as the object graph is serialized) are listed below:

• The 200 OK response sent with an empty response body when using the ResponseCompression middleware is an issue which is likely to catch people out.

• Without ResponseCompression middleware, the 200 OK response with a truncated JSON body is not as bad as it results in invalid JSON, but is still inconsistent with the returned status code, so this behaviour should not be the default configuration, ie Response Buffering should be on by default to allow the error to be captured and the correct status code and response returned.

• It is not possible to capture and therefore log a serialization error, the error is only reported by kestrel.

The inconsistent error handling with no way to capture exceptions under all circumstances is a big issue, this is especially important when it is not possible to indicate to consumers of your API that a serialization error occurred in the response.

As i have stated already, it is possible using Node Express to intercept an equivalent chunked response and append text to the body to add error information. It is also possible to capture and log the errors when this occurs unlike in .Net Core where there seems to be no way of capturing the exception in code to log it.

[Eilon]

@Tratcher / @davidfowl - do you have thoughts on what, if anything, we should consider changing or improving in these cases? A missing feature? Obscure bizarre behavior that we should tweak?

[Tratcher]

As an alternative to buffering is there any way for the serializer to sanity check the model (possibly only in dev?) for likely errors like recursion before it triggers the start of the response?

[Eilon]

@Tratcher there might be, but then you might as well just buffer the response (unless your data structure has a lot of raw data and very little structure). Also, it would of course be a per-scenario fix (we couldn't fix it generally in ASP.NET Core).

I'm not sure what else we could do...

[halter73]

One thing we could look into is firing ExceptionFilters/Handlers for serialization errors. Based on the above comment by @chrisckc, that's not happening today.

With the developer exception page enabled, we could also consider appending error details to the response body even after a response has been partially written. I created #2587 suggesting this idea. It's currently in the 2.2.0-preview1 milestone.

[Tratcher]

They don't fire because the response has already started. Corrupting the response is not a viable option.
#2587 (comment)