Json Serializer ReferenceLoopHandling Issue?

[chrisckc]

Hi, I think i may have found an issue when using ReferenceLoopHandling.Error (which seems to be the default), in an MVC Web Api that i am working on. In my scenario i tried loading an entity and its related set of nested entities using the .Include() syntax. I then outputted the set of nested entities in the controller and did not see the result i expected. (I expected an exception be thrown)

Inspecting the resulting object graph before serialization shows that it contains self referencing loops because the context automatically linked up each nested entity back to its parent entity, which itself contains the same nested entities each linked back to their parent entities and so on.

When the controller then serialized the object graph using the json.net ReferenceLoopHandling.Error option, i expected to see an exception raised as per the json.net documentation.

What i found it that no exception is raised, instead the resulting Json outputted by the controller seems to be truncated at the point where i would expect that the circular reference was detected/encountered during serialization.

What i can see from looking at the Json is an array as the root element as expected, but the array only contains the first entity representation (several are present before serialization) and this is only a partial representation, all of the properties that would normally be seen listed after the parent entity navigation property are missing from the representation, however the Json appears to be valid containing the correct closing braces etc.

Here is the pseudo code in the controller:

Owner owner = _dbContext.Owners.Include(item => item.Dogs).Where(item => item.OwnerId == id).FirstOrDefault();
if (owner == null)
{
    return NotFound();
} 
else
{
    IEnumerable<Dogs> dogs = owner.Dogs.ToList();
    return Ok(dogs);
}

Using the "ReferenceLoopHandling.Error" option, the resulting Json is like this:

[
  {
    "dogId": "20000004-1111-1111-1111-111111111111",
    "dogName": "Fido",
    "dogPurchaseDate": "2016-09-29T04:31:00+00:00",
    "owner": {
      "ownerId": "10000000-1111-1111-1111-111111111111",
      "ownerName": "Fred",
      "dogs": []
    }
  }
]

Instead of an exception, i have valid Json but with only the first dog entity outputted and there are Dog properties missing that would normally be listed after the "owner" property. This looks as if the json.net exception is being swallowed somewhere, is this behaviour by design? I would have thought it be essential that an exception is thrown when a loop is detected to avoid unpredictable output.

If i use ReferenceLoopHandling.Ignore, then all of the Dog entities are outputted correctly and owner property of each Dog entity includes the list of nested dog entities except for its own parent Dog entity, which is what i would expect as per the json.net documentation. That kind of output is not what i want as it is very bloated, its just to show the difference in the behaviour of the 2 options during some testing.

I believe this is an EF/MVC issue rather than a json.net issue because if i do this:

//configure the same options used in startup.cs
JsonSerializerSettings settings = new JsonSerializerSettings {
    ContractResolver = new CamelCasePropertyNamesContractResolver(),
    Formatting = Formatting.Indented,
    NullValueHandling = NullValueHandling.Include,
    MissingMemberHandling = MissingMemberHandling.Ignore,
    ReferenceLoopHandling = ReferenceLoopHandling.Error
};
settings.Converters.Add(new StringEnumConverter());
//now try to serialize the dogs...
string jsonString = JsonConvert.SerializeObject(dogs, settings);

I correctly get an exception: Self referencing loop detected with type 'WebAPIApplication.Data.Dog'. Path '[0].Owner.Dogs'."

The controller is using json.net for serialization under the hood, so surely this exception should bubble up to the controller rather then be swallowed and result in a partial Json output.

Here is my json serializer startup.cs config:

public void ConfigureServices(IServiceCollection services)
{
//other code.........
builder.AddJsonOptions(
o =>
{
    o.SerializerSettings.ContractResolver = new CamelCasePropertyNamesContractResolver();
    o.SerializerSettings.Converters.Add(new StringEnumConverter());
    o.SerializerSettings.Formatting = Formatting.Indented;
    o.SerializerSettings.NullValueHandling = NullValueHandling.Include;
    o.SerializerSettings.MissingMemberHandling = MissingMemberHandling.Ignore;
    o.SerializerSettings.ReferenceLoopHandling = ReferenceLoopHandling.Error;
});

project.json package versions: "Microsoft.AspNetCore.Mvc": "1.0.1", "Npgsql.EntityFrameworkCore.PostgreSQL": "1.0.2-", "Npgsql.EntityFrameworkCore.PostgreSQL.Design": "1.0.2-"

Looking at other issues logged here it seems like this has occurred previously and has been worked around/avoided so maybe the root cause has not yet been resolved. It also seems that the behaviour may have been different in older versions?

Issue 4160 mentions the Json truncation, however there seems to be some circular referencing going on in these 2 issues.... https://github.com/aspnet/Mvc/issues/4160 That issue has been closed and refers to this one instead: https://github.com/aspnet/EntityFramework/issues/4646 which then just changes the subject to view models etc. and is closed, referring back to 4160

This also seems similair: https://github.com/aspnet/EntityFramework/issues/5429

[gdoron]

It really has nothing to do with EF. You can mimic the same thing with arrays and"normal" instances.

[chrisckc]

Indeed you can but that's not the point, it may well have nothing to do with EF, more likely just MVC, i don't know enough about it to comment any further on that. The point is that JsonConvert.SerializeObject correctly throws an exception but MVC seems to be swallowing it and outputting an OK status code with a truncated Json representation which surely is a bad thing to do?

[divega]

@glennc does the last comment sound familiar?

[divega]

Just to follow up on this: The reason I pinged @glennc is that he had mentioned to me some issue in ASP.NET Core (which was presumably already fixed in recent builds) could cause this exception to be swallowed, and I was reminded of that by this paragraph:

The controller is using json.net for serialization under the hood, so surely this exception should bubble up to the controller rather then be swallowed and result in a partial Json output.

CC @rynowak as well in case it rings a bell for him.

Other than this, @gdoron already correctly mentioned that this is not really an issue with EF but a general issue with serialization with graphs of objects with Json. Closing as external.

[chrisckc]

So this won't be an issue in v1.1 meaning i will see an exception rather than partial a Json representation? When is v1.1 due to be released?

[divega]

@chrisckc I talked to @glennc in person. The issue with the exception being swallowed is actually still being worked on: https://github.com/aspnet/IISIntegration/issues/39.

[chrisckc]

Thanks @glennc, I noticed your comment in the issue you just referenced, i just want to add that i am developing and running my .NetCore WebApi experimental app on a Mac using VSCode. I really like the new cross platform abilities!

The project was generated using the yeoman aspnet WebApi template (2 or 3 weeks ago), default config using Kestrel etc. This is my host config:

var host = new WebHostBuilder()
                .UseConfiguration(config)
                .UseKestrel()
                .UseContentRoot(Directory.GetCurrentDirectory())
                .UseIISIntegration()
                .UseStartup<Startup>()
                .Build();

[divega]

@chrisckc so if I understand what you are saying, you suspect this could be an outstanding issue with Kestrel? Similar issues were previously discussed in https://github.com/aspnet/KestrelHttpServer/issues/341#issuecomment-155245802 but they are believed to be resolved. Definitively create a new issue or comment in one of the existing issues in one of those repos (whichever seems the most appropriate to you). It would be great if you could provide a full repro. BTW, another thing I would suggest is to try different browsers.

[halter73]

@chrisckc I think part of the problem is that the exception that is occurring happens after your controller action returns it's ActionResult.

For efficiency reasons, return Ok(dogs); doesn't block waiting for dogs to be serialized or for the response to be written, so by the time the exception is thrown during serialization it's too late for an exception to be thrown in your action which at this point has already completed. I bet this exception could be handled by some sort of action filter (@rynowak would certainly know), and if not there in some custom middleware.

I highly recommend setting up the developer exception page (only for development of course) which should show you what exception is being thrown and where. Adding a console logger to your application can also help you track down errors like this during development.

You mentioned that it seems wrong that a 200 response was received. This happens because the object isn't completely serialized prior to writing response, so by the time the exception is thrown the start of the object (and the 200 status) has already been written. If you look at your browser's developer tools, you should see some indication that the response is incomplete/invalid because the chunked terminator wasn't written. (Unless you're running behind IIS and running into aspnet/IISIntegration#39)

[chrisckc]

@glennc yes, my understanding is that when running the app in VSCode on a Mac the requests just go direct to Kestrel rather than proxied through IIS when using VS 2015 on windows. Ill provide a demo soon.

@halter73 I am using the developer exception page but it only seems o pickup out of band exceptions so doesnt see exceptions inside the controller method. I am also using console logger and didn't remember seeing anything useful in the output.

Your comment about the response serialization mechanism is interesting, ill check the response in more detail, i used postman for my testing.

[glennc]

@chrisckc Your understanding is correct. You aren't being proxied when you just run from the terminal on your Mac. So the IIS issue isn't biting you here.

[chrisckc]

Ok, here is a repo that demonstrates the issue, no EF in this, just an in-memory objects implementation based on the TodoApi from the aspnet documentation with a few extras.

https://github.com/chrisckc/TodoApiDemo

Refer to the notes in readme.md to see how to reproduce the issue.

@halter73 I forgot i was using a global exception filter which seems override the dev exception page. I also re-checked the console log and found some useful info.

@divega @glennc So this is indeed a Kestrel issue then, spotted this in the console log:

Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware:Warning: The response has already started, the error page middleware will not be executed.
Microsoft.AspNetCore.Server.Kestrel:Error: Connection id "0HKVJ34SUMOMU": 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'.
...........stacktrace etc............
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 91.7335ms 200 application/json; charset=utf-8

Also I don't think the DeveloperExceptionPage Middleware should be behaving as it should, but im sure there will be a valid reason / restriction somewhere.

I also have a global exception filter plugged in in my startup.cs which never gets called unless i serialize the array in the controller first by using JsonConvert.SerializeObject

// Setup global exception filter
builder.AddMvcOptions(o => { o.Filters.Add(new GlobalExceptionFilter(this.LoggerFactory)); });

In the scheme of things i think this is an important issue because the client using the Api will never know that there has been an error on the server when only 1 of the 3 note objects are serialized, the Json is valid and the status code is still 200, falsely indicating a successful response... A UI which shows the data will be end up showing incorrect results.

I would not want to have to rely on developers working on an Api to always avoid falling into this trapdoor by either using ReferenceLoopHandling.Ignore or correctly attributing the model with [JsonIgnore] attributes to prevent loops... What about other kinds of serialization issues?

Does someone want to decide where this issue should sit? Thanks!

[halter73]

Also I don't think the DeveloperExceptionPage Middleware should be behaving as it should, but im sure there will be a valid reason / restriction somewhere.

The likely issue with the DeveloperExceptionPage for this exception is that it happens after a response is partially written. At that point it isn't possible to write a developer exception page since the response is already corrupted.

[chrisckc]

Just cloned my demo repo to my Windows VM and found that the behaviour is the same, with the same output in the console log. Note that VS2015 is unable to restore the packages, seems to be due to issue: dotnet/cli/issues/4248 so you have to use dotnet restore from the command line instead.

@halter73 I think that writing the response before it is known that the object can be completely serialized without error is problematic because like you say it will prevent any serialization errors from being handled properly. It will even prevent the return of just an error status code so providing no indication that there has been a problem.

In any performance vs reliability tradeoff, i think reliability and consistency should be more important for any framework aimed at enterprise usage?

[halter73]

@chrisckc I tried your TodoAPI demo. It looks like you are indeed running into aspnet/IISIntegration#39. If you hit Kestrel directly, you get an invalid response. When I tested I had Kestrel running directly on port 5000 and IIS running on port 12345.

This is what I see when calling the Invoke-WebRequest powershell commandlet on both endpoints:

And the same from Chrome:

In both cases the response only appears successful when proxied by IIS. The raw fiddler output for the request shows the difference in the responses.

The "0" on the last line you see at the end of the IIS response is required to indicate a successful response. IIS shouldn't be adding the "0" when it isn't sent by Kestrel which is what aspnet/IISIntegration#39 is about.

Note: Instead of calling loggerFactory.AddConsole(Configuration.GetSection("Logging")), I suggest calling the parameterless version loggerFactory.AddConsole() to write out logs from all sources. At least until you have an appsettings.json with the namespaces you want to log configured.

[divega]

@halter73 is it actionable though? I would like to move this issue to a repo where it can be addressed. Any clue where it should belong?

[halter73]

@divega https://github.com/aspnet/IISIntegration/issues/39 is actionable. I think that's the biggest issue brought up and should be fixed ASAP.

@halter73 I think that writing the response before it is known that the object can be completely serialized without error is problematic ...

It can certainly see how it can be problematic, but as you mention it's a trade off. For small objects it probably would make sense to pre-serialize, but we've had customers send multi-megabyte JSON objects in which case that would be very inefficient.

We could try to dynamically change behavior based on size, but I'm afraid that would lead to more confusion. Another possibility is to both serialize and write to the response body inside the controller action asynchronously. While this is possible, it doesn't really fit the normal usage pattern for MVC where response objects are returned and serialized after the Action returns an object.

[chrisckc]

@halter73 I can confirm i have just observed the same behaviour you described running on Windows, the response shows an error in chrome dev console from Kestrel but not IIS.

I checked the chrome developer console on my Mac and can also see the ERR_INCOMPLETE_CHUNKED_ENCODING, i had not noticed that before as i have been using postman on my Mac (no fiddler equivalent) and it provides no indication of any anomaly in the response inspectors.

I suspect that if i use one of the popular REST client libraries on an iOS device to consume the Api from kestrel that they too will not see an issue with the response, or just get confused because of the 200 status code. I will attempt this soon to see what happens.

[chrisckc]

@halter73 @divega Ideally i would like the behaviour to be configurable, maybe on a per controller basis so at least we have the option for complete reliability. For small payloads i suspect the performance difference will be negligible, large payloads should not be an issue in theory as a well designed Api should not be attempting to send large payloads anyway. (should be broken down etc.)

If it were configurable, customers who wish to send large payloads and are either:

1. confident that all payloads will serialize correctly using json.net
2. they control the clients or know that they are able to detect an incomplete payload can configure their controllers accordingly for their own needs.

[halter73]

@chrisckc

Ideally i would like the behaviour to be configurable, maybe on a per controller basis so at least we have the option for complete reliability.

This isn't a per-controller configuration, but it looks like https://www.nuget.org/packages/Microsoft.AspNetCore.Buffering/ might give you what you're looking for. This won't cause the exception to be raised from inside the Action method, but this will allow for the response to be rewritten to a 500 (whith the DeveloperExceptionPage if that's configured) when the exception is thrown during serialization. This should also work around the IIS issue.

This SO post shows how to use it: https://stackoverflow.com/questions/37966039/disable-chunking-in-asp-net-core

The buffering should probably be set up after the DeveloperExceptionPage but before MVC, but it should still work if you call app.UseResponseBuffering() before both.

[divega]

This issue was moved to aspnet/IISIntegration#285