Logged json missing bracket

[wendilimMS]

When logging json messages with objects that contain a collection of objects, a bracket gets dropped, making the json invalid. I have tested with a json object that has an empty collection, and a json object that has a collection of strings, and both of them are logged perfectly. Example:

// this is how the json object should look like
{
    "approvedDateTime": null,
    "approverAlias": null,
    "contentDescription": null,
    "description": null,
    "expectedCommunicationFrequency": null,
    "expirationDateTime": null,
    "id": "db84cbc8-12b0-4149-b670-97561fab68fe",
    "name": "Graham, Donnelly and Leffler",
    "owners": [], // populated collections of values does not affect the printing.
    "sponsors": [],
    "state": 0,
    "topicLocales": [{  // this is my collection of objects. If this were empty, this works.
        "approvedDateTime": null,
        "approverAlias": null,
        "createdBy": null,
        "createdDateTime": "2016-10-18T17:33:12.5752723Z",
        "cultureName": "en-US",
        "footerLanguage": "en",
        "lastModifiedBy": null,
        "lastModifiedDateTime": null,
        "localizedDescription": "leverage magnetic e-markets",
        "localizedName": "Gusikowski-Miller",
        "state": 0
    }],
    "topicNamespaceId": "2fbba100-9f45-41ed-86b7-143e5b14d7c0",
    "topicTags": [], 
    "createdBy": null,
    "createdDateTime": "2016-10-18T17:33:12.5752723Z",
    "lastModifiedBy": null,
    "lastModifiedDateTime": null
}

We have a template for the message that resembles this: @"{{'timestamp': '{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz}', 'level': '{Level}', 'message': '{Message}', 'exception': '{Exception}'}}{NewLine}" However the message that prints out is:

{
    'timestamp': '2016-10-18 17:33:12.622 +00:00',
    'level': 'Warning',
    'message': '{"eventId":1101,"eventName":"TopicCreated","message":"A topic has been created","state":{"approvedDateTime":null,"approverAlias":null,"contentDescription":null,"description":null,"expectedCommunicationFrequency":null,"expirationDateTime":null,"id":"db84cbc8-12b0-4149-b670-97561fab68fe","name":"Graham, Donnelly and Leffler","owners":[],"sponsors":[],"state":0,"topicLocales":[{"approvedDateTime":null,"approverAlias":null,"createdBy":null,"createdDateTime":"2016-10-18T17:33:12.5752723Z","cultureName":"en-US","footerLanguage":"en","lastModifiedBy":null,"lastModifiedDateTime":null,"localizedDescription":"leverage magnetic e-markets","localizedName":"Gusikowski-Miller","state":0}],"topicNamespaceId":"2fbba100-9f45-41ed-86b7-143e5b14d7c0","topicTags":[],"createdBy":null,"createdDateTime":"2016-10-18T17:33:12.5752723Z","lastModifiedBy":null,"lastModifiedDateTime":null}', //<-- missing bracket here
    'exception': ''
}

Currently using Microsoft.Extensions.Logging.AzureWebAppDiagnostics v1.1.0-alpha1-22167 alongside Newtonsoft.Json v9.0.1 to serialize the message before logging.

[muratg]

Can you give us a simple repro app, ideally on a github repo?

[wendilimMS]

Hi Murat, Thanks for the quick response. There would be quite a bit of effort involved to isolate the code we use for logging into a separate repo (we are currently on VSTS), and in doing so we might inadvertently remove the issue – is there any alternative information that you would need?

[muratg]

@wendilimMS I recommend starting a new app from template, add the dependencies as necessary and do basic logging to repro this. If there's a bug in the framework somewhere, this shouldn't be hard to repro.

Unfortunately, not knowing your app, it's hard to see what may be going wrong, apart from that it may be a user error as a wild guess.

[wendilimMS]

It would strange for it to be a user error considering that it only does not work for the case where the json contains a collection of objects. We have several other objects that have different properties, and the common failing point is that when we try to log an object that contains a collection of objects, the logged json contains a missing bracket. Would you be able to point me in any other direction of investigation other than "user error"?

---

From: Murat Girgin notifications@github.com Sent: Tuesday, October 18, 2016 11:31:24 AM To: aspnet/Logging Cc: Wen Di Lim; Mention Subject: Re: [aspnet/Logging] Logged json missing bracket (#503)

@wendilimMShttps://github.com/wendilimMS I recommend starting a new app from template, add the dependencies as necessary and do basic logging to repro this. If there's a bug in the framework somewhere, this shouldn't be hard to repro.

Unfortunately, not knowing your app, it's hard to see what may be going wrong, apart from that it may be a user error as a wild guess.

You are receiving this because you were mentioned. Reply to this email directly, view it on GitHubhttps://github.com/aspnet/Logging/issues/503#issuecomment-254597552, or mute the threadhttps://github.com/notifications/unsubscribe-auth/AVaxmPGPNzAqPQHLIgF2cN6oKuXlCgRIks5q1RB8gaJpZM4KaF8y.

[muratg]

Sorry, I am not sure without knowing what your app does or how it uses the libraries. If you're unable to provide simple repro steps or a repro app, we won't be able to debug it. If this is the case, the most I can recommend you would be to debug the whole stack yourself (since it's open source, you can use the source code of your dependencies instead of the package even).

[BrennanConroy]

You can add other loggers to see if it is just the Azure Logger that has this issue.

[wendilimMS]

Hi, I've set up a dummy project that reproduces the problem successfully: https://github.com/wendilimMS/AzureBugRepro/tree/master/AzureBugRepro.

To reproduce the issue, make a post to /api/values with the following input:

{
    "name" : "Some name",
    "valueCollection": ["7dfdc479-7b76-4a58-8c98-7d1afefa7256"],
    "objectCollection": [{
        "name" : "Some other name",
        "lastModified": "2016-10-18T20:53:45.488Z"
    }]
}

Please let me know if my user input is actually incorrect.

[BrennanConroy]

This is most likely a bug in Serilog The OutputTemplate you set gets passed directly to Serilog and they parse it here https://github.com/serilog/serilog/blob/32e0c9578db720add74720bceb62bd46967694c4/src/Serilog/Parsing/MessageTemplateParser.cs#L41

[wendilimMS]

Ok, thanks. I'll log an issue with them.

[nblumhardt]

Just checking out the sample app, this line is a bit questionable: https://github.com/wendilimMS/AzureBugRepro/blob/master/AzureBugRepro/LoggerExtensions.cs#L35

string message = JsonConvert.SerializeObject(info, JsonSerializerSettings);
logger.LogWarning(message);

If the logging pipeline is going to format the message into a field in a JSON object, won't this always end up escaped anyway?

To get the object through as structured data, if it's Serilog on the back-end, you can do:

logger.LogWarning("Some info {@info}", info);

I think regardless of the Serilog tokenizer's handling of the message, the fact that the payload is structured data will need to be communicated to the logger if the result is intended to be readable as JSON.

[wendilimMS]

The logging pipeline itself does not format the message into a JSON object. I had a quick look at what the output of your suggestion would produce, and it seems to have simply inserted the object.

{'timestamp': '2016-10-20 22:49:07.228 +00:00', 'level': 'Warning', 'message': 'DiagnosticInfo`1 { EventId: 1001, EventName: "MyObjectCreated", Message: "An object has been created", State: MyObject { Name: "Some name", ValueCollection: [7dfdc479-7b76-4a58-8c98-7d1afefa7256], ObjectCollection: [MyObjectDetail { Name: "Some other name", LastModified: 10/18/2016 20:53:45 }], LastModified: null, PropertyA: null, PropertyB: null, PropertyC: null, Option: null } }', 'exception': ''}

As you can see, the message in question will still not be valid json, or in any deserializable format. The idea is to be able to parse the logged message to obtain various property values as well as to be able to deserialize the original object as well, hence why we required json in the first place.

[nblumhardt]

Thanks for the follow-up @wendilimMS; you're quite right, unless Serilog is configured to log JSON the result still won't be JSON, as you pointed out.

You could do this to get the JSON string through untouched:

string message = JsonConvert.SerializeObject(info, JsonSerializerSettings);
logger.LogWarning("{Message:l}", message);

But this is still side-stepping the main issue - Serilog really needs to be configured with a JSON formatter to work nicely in this scenario.

For example, when you format in {Exception}, you'll hit problems if the exception message contains " or \. If the exception message is, for example, Could not open "file.txt", then when it's inserted into the template the " characters will result in malformed JSON.

Perhaps this does come back to the Azure web app diagnostics API?

The configuration currently looks like:

loggerFactory.AddAzureWebAppDiagnostics(new AzureWebAppDiagnosticsSettings
{
     BlobName = "api.txt",
     OutputTemplate = @"{{'timestamp': '{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz}', 'level': '{Level}', 'message': '{Message}', 'exception': '{Exception}'}}{NewLine}"
});

If the output is wanted in JSON format, how about:

loggerFactory.AddAzureWebAppDiagnostics(new AzureWebAppDiagnosticsSettings
{
     BlobName = "api.json",
     Formatter = Formatters.Json
});

Under the hood, this would configure Serilog with a JSON output formatter (e.g. CompactJsonFormatter), and issues like the exception message encoding would go away.

(I say this without knowing whether JSON logging is aligned with the goals of Azure Web App diagnostics, of course.)

Does this help?

Cheers, Nick

[wendilimMS]

Thanks Nick, getting the JSON string through untouched seems to be a good enough work around (until some other input breaks it). It would be good if AzureDiagnostics did have an option to specify that the message requires a JSON formatter, but for now this will have to do.

[muratg]

We are closing this issue because no further action is planned for this issue. If you still have any issues or questions, please log a new issue with any additional details that you have.