Nlog: JsonLayout ignores capturing directives in structured log events

[nblumhardt]

Type (choose one):

• Bug

NLog version: (e.g. 4.5.0-rc04)

Platform: .NET Core

Current NLog config (xml or C#, if relevant)

using System;
using NLog;
using NLog.Targets;
using NLog.Config;
using NLog.Layouts;

namespace nlog_json
{
    class Program
    {
        static void Main(string[] args)
        {
            var config = new LoggingConfiguration();
            var consoleTarget = new ColoredConsoleTarget();
            config.AddTarget("console", consoleTarget);
            var json = new JsonLayout();

            // Include the event properties in the JSON
            json.IncludeAllProperties = true;

            consoleTarget.Layout = json;
            config.LoggingRules.Add(new LoggingRule("*", LogLevel.Debug, consoleTarget));
            LogManager.Configuration = config;

            var logger = LogManager.GetLogger("Example");
            logger.Info("Hello, {Person}", new { Name = "nblumhardt" });
        }
    }
}

Expected

The Person property is serialized using its ToString() representation:

{"Person": "{ Name = nblumhardt }"}

Actual

The property value is serialized:

{ "Person": {"Name":"nblumhardt"} }

This is unexpected, because message templates use @ to control serialization. It's an opt-in; if the property name is not prefixed with @, then a string is captured just like in .NET format strings.

If we're going to do structured logging with JsonLayout, we shouldn't risk accidentally serializing-the-world. (The canonical footgun here would be if Person captured an entity from Entity Framework - these ToString() fine just like everything else, but tend to serialize very poorly.)

[snakefoot]

It works as expected. JsonLayout will by default serialize everything as Json.

When IncludeAllProperties = true, then it will serialize all property values into Json.

JsonLayout doesn't have any clue about MessageTemplate-syntax.

If you don't want to have properties serialized as Json, then configure IncludeAllProperties = false.

[nblumhardt]

Thanks for the reply, @snakefoot, appreciate you taking the time to answer.

What's the recommended approach for serializing structured log events? The typical use case for structured logging is generally _templated properties -> JSON -> (file or data store)_. This behavior will make it impractical to use templated properties for structured logging, which seems to defeat the whole purpose of including the feature in 4.5.

• IncludeProperties = true - I can't do structured logging because of the risk I'll end up serializing things that shouldn't be serialized
• IncludeProperties = false - I can't do structured logging because the interesting data captured in the log events won't be included in the JSON output

It seems like the structured logging story is going to be very limited if the two sides of the feature - capturing structured event data and formatting out JSON - don't work in harmony.

I could be missing something, apologies if I'm overlooking the obvious - still wrapping my head around how NLog fits together in this regard. Cheers!

[snakefoot]

@nblumhardt It is comments like these, that #2332 was created for. But better now than never.

Think we can adjust JsonLayout so the parameters captured using message-template uses the formatting extracted from the message-template.

[snakefoot]

@nblumhardt Would it make sense that when accessing the message-template-parameters through the LogEventInfo.Properties? Then they were already converted according to their message-template-format (unless specified to be serialized into Json, or primitive types).

Then there would be no surprises, but I guess the JsonLayout is probably the only one doing aggressive reflection.

[nblumhardt]

Hey, thanks for the follow-up, @snakefoot.

It is comments like these, that #2332 was created for.

You didn't spot my username in that thread? :-)

It sounds like either approach could work; I'd be more inclined to try pre-processing the values through an API on LogEventInfo - in the long run, more consumers than just JsonLayout will want to capture the correct values for structured event properties.

Just having JsonLayout participate in this would be a good measure in the short-term.

[snakefoot]

@nblumhardt Could you try and test with this custom build created from #2555 (load it from local-nuget-repository):

https://ci.appveyor.com/project/nlog/nlog/build/4.5.0-beta7078/artifacts

P.S. Might have to clear your local nuget-cache, as the version-number is unchanged. So it might use the rc04 retrieved from the official nuget-provider.

[nblumhardt]

Hi Rolf - a quick smoke test with the new binary appears to work as expected 👍 🎉

[snakefoot]

@nblumhardt Thank you for testing. Have generated a rather large pile of PRs to review for NLog 4.5-rc05, so not sure when a new build with be ready on nuget.

[304NotModified]

I hope next week. This weekend I'm already full, will try to find some time from Monday

[304NotModified]

Not sure if I followed everything correctly:

This is unexpected, because message templates use @ to control serialization. It's an opt-in; if the property name is not prefixed with @, then a string is captured just like in .NET format strings.

This is expected to me, as the @ controls serialization in the message and not in the event properties. The event-properties are objects and in the config the user should control how it's serialized (json, xml, flat etc).

So I think i'm not sure if #2555 is a good approach (thanks again for the PR @snakefoot )

This behavior will make it impractical to use templated properties for structured logging, which seems to defeat the whole purpose of including the feature in 4.5.

IncludeProperties = true - I can't do structured logging because of the risk I'll end up serializing things that shouldn't be serialized
IncludeProperties = false - I can't do structured logging because the interesting data captured in the log events won't be included in the JSON output

I understand the issue. I'm fine by adding a extra option to the JSON layout, but afaik it should serialize all objects by default. The JSON layout is also used for other things then structured logging!

If i'm missing something, please correct me!

[snakefoot]

I understand the issue. I'm fine by adding a extra option to the JSON layout, but afaik it should serialize
all objects by default. The JSON layout is also used for other things then structured logging!

The JsonLayout have never done reflection of LogEventInfo.Properties. This is something that have just been added for NLog 4.5.

The MessageTemplate-parameters are injected into the LogEventInfo.Properties, but the MessageTemplate also works as a restriction of how the paremeters should be treated. This helps in the case with the Entity-framework-objects.

Right now the NLog 4.4 doesn't attempt reflection in JsonLayout, but just performs ToString, changing this would be a breaking change in NLog 4.5.

One could consider to add a new option to JsonLayout, whether it should attempt reflection for all properties (Also MDLC, MDC)

[304NotModified]

Right now the NLog 4.4 doesn't attempt reflection in JsonLayout, but just performs ToString, changing this would be a breaking change in NLog 4.5.

good point, but do you agree that the structured logging prefixes should not influence the JSON layout? That's merely my concern.

About the breaking change, it's a bug/known issue IMO in NLog < 4.5

[snakefoot]

About the breaking change, it's a bug/known issue IMO in NLog < 4.5

That is just until someone gets surprised that the ToString is not called on the custom-object (as it did before in Nlog 4.4), but instead it performs aggressive reflection and outputs the entire datamodel (after upgrading to NLog 4.5)

Think the most requested feature was the ability to output the contents of a dictionary/list, instead of just calling ToString(). Have not seen requests for aggressive reflection on all objects.

good point, but do you agree that the structured logging prefixes should not influence the JSON layout? That's merely my concern.

I think there should be an option on JsonLayout whether it should attempt aggressive reflection of all objects (LogEventInfo.Properties, MDC, MDLC, etc.). The default value of this option could then be changed with NLog 5.0 (Maybe it could have aggression-flags. Ex. Traverse enumerable but still do ToString on custom objects).

Examples of aggression-flags:

• Traverse list/dictionaries
• Reflection on Value-Tuples
• Reflection on Exceptions
• Reflection on MessageTemplate Properties
• Reflection on normal LogEventInfo.Properties
• Reflection on MDLC properties
• Reflection on MDC properties

[nblumhardt]

FWIW, the @ in a message template is intended to be a capturing operator, not a way to control display formatting. Unintended serialization has been the source of a lot of headaches through Serilog's evolution - having @ as a opt-in to serialization is a really important safety feature for us.

There are a few places where we do capture one level of structure without @ - those are enumerable objects (lists/arrays), and tuples. Without @, an array (for example) will be captured, but the values in it will still be ToString()/value captured. The @ is still required to do deep serialization of arrays.

This is why we also support $ in message templates - it's a way of forcing ToString() when another rule (like the default array/tuple capturing) would be triggered. This is useful to prevent serialization in some situations where an arbitrary object is being logged for the sake of recording its identity, rather than its contents.

Hope this helps, and let me know if I can fill in any more details of how we've handled this kind of thing elsewhere 👍

[snakefoot]

@nblumhardt & @304NotModified Have now added a new property to JsonLayout called MaxRecursionLimit

The default value is 0, which means it will not attempt property-reflection by default, but only when the message-template says it is safe. I have changed so collections at initial level will not receive penalty, so when using default value 0, then it will allow enumeration of collections (but not collections of collections).

When value is 1 then it will allow very limited object property reflection.

When value is 10 then it will use the default recursion level of the NLog JsonConverter.

[304NotModified]

@snakefoot cool!

To make things clear:

FWIW, the @ in a message template is intended to be a capturing operator, not a way to control display formatting. Unintended serialization has been the source of a lot of headaches through Serilog's evolution - having @ as a opt-in to serialization is a really important safety feature for us.

In NLog it's important that the config (file) should have full control over the formatting (JSON/XML) and that it's independent of the logging statements. There was no control of the message formatting (${message} to be clear) and so structural logging and the @ and $ operators makes sense.

So it's OK to me that the JSON layout has defaults to serialize by default, as long as it serialization/deconstruction is fully configurable in the config of the JSON layout - i'm not sure if that's now the case with #2555 (I need to look at the latest changes)

[snakefoot]

@nblumhardt If #2555 is approved, then you "just" have to configure this JsonLayout setting: MaxRecursionLimit="0" (Initial default value, but will probably change in newer version, so good idea to set it explicitly). Then it should behave just like Serilog (Enumerating collections automatically, but not doing property-reflection on objects without explicit use of @)

[nblumhardt]

Thanks for keeping me in the loop! MaxRecursionLimit="0" sounds like the right behavior 👍

(To me, using deep serialization by default sounds like a massive and easily-avoidable footgun, but I'm not at all familiar with how NLog is expected to behave. Just so it's absolutely clear, the big problems with deep serialization of arbitrary types, even if the recursion depth is limited, are:

• some hierarchies are super-broad, e.g. within a depth of 5, serializing a System.Type can generate gigabytes (Type.Assembly.DeclaredTypes..., etc),
• some property accessors are slow, e.g. lazily-loaded entity relationships, meaning even a depth of 5 is enough to lead to multi-second, or even multi-minute, latency,
• some property accessors throw because they don't expect to be called without other invariants being cheked first, and,
• some property accessors are not thread-safe; the logging thread might have access to one safe part of the object graph, but traversing properties can cause get access to non-thread-safe, side-effect-causing accessors on other objects, leading to state corruption or deadlocks.

If you want to explore this any further let me know - otherwise, over and out from me, I'll update _NLog.Targets.Seq_ as soon as a new RC is out. Cheers!)

[snakefoot]

@nblumhardt NLog 4.5 is the first version of NLog, that is able to perform object-reflection when doing JSON. I also prefer to keep this reflection-feature under control, so users doesn't get hit by lightning.

NLog 4.5 BETA/RC is doing object-reflection by default. This allowed this new reflection-feature to get some user exposure. But I think it should be locked down with the NLog 4.5 RTM.

[304NotModified]

Rc5 is now live :)

[nblumhardt]

👍 🎉

I've updated, I seem to be hitting an infinite loop in TemplateEnumerator.MoveNext(). Guessing it is my problem, will debug deeper shortly, but if you're curious you can grab the branch from the PR in https://github.com/datalust/nlog-targets-seq/pull/27 :-)

[304NotModified]

Have any stracktrace?

[snakefoot]

In MessageTemplateParameters.cs there is these lines:

isPositional = false;
if (holeIndex != 0)

It should instead be:

if (isPositional)
{
isPositional = false;
if (holeIndex != 0)

Sorry about this.

[snakefoot]

Will fix the unit tests to exercise both MessageTemplateParameters and the TemplateRenderer when removing the old Template code

[snakefoot]

Great job with getting rc5 ready. Think we are close. Regarding the issue with missing LogEvent Properties when using NetworkTarget alone, then I think there is missing a call to Target.MergeLogEventProperties in NetworkTarget. My pending PR for logger callsite makes MergeLogEventProperties obsolete

[304NotModified]

In MessageTemplateParameters.cs there is these lines:
isPositional = false;
if (holeIndex != 0)
It should instead be:
if (isPositional)
{
isPositional = false;
if (holeIndex != 0)
Sorry about this.

Added https://github.com/NLog/NLog/pull/2576. Any idea how I could unit test this easily?

[snakefoot]

Think you just need a template with two named parameters

[snakefoot]

Your change is wrong it should not be:

else if (isPositioal)

Instead you should do like I wrote:

else
{
if (isPositional)
{
isPositional = false;
if (holeIndex != 0)
{
// rewind
continue;
}
}

// add parameter

[snakefoot]

Expand my previous comment to see a more detailed code change.

[snakefoot]

Regarding unit test then you can change the ParserTests to use the MessageTemplateParameters instead (Except ParseAndPrint)

[304NotModified]

Thanks, will try to fix this tomorrow

[snakefoot]

No need to use short (16 bit) since new processors prefer 32 bit and 64 bit variables.

Also no need to perform "safe" lookup, as invalid templates should trigger exceptions (just not unhandled exceptions)

Planning to add a minor improvement, so it will cache the parsing result if not IsPositional by creating the PropertiesDictionary in LogEventInfo.

Sent from my Samsung device

-------- Original message --------
From: Julian Verdurmen [e-mail]
Date: 14/02/2018 19:54 (GMT+00:00)
To: NLog/NLog [e-mail]
Cc: Rolf Kristensen [e-mail], Mention [e-mail]
Subject: Re: [NLog/NLog] JsonLayout ignores capturing directives in structured log events (#2557)

Thanks, will try to fix this tomorrow

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://github.com/NLog/NLog/issues/2557#issuecomment-365725762, or mute the threadhttps://github.com/notifications/unsubscribe-auth/AK-fnKhxd1QGDVdGYSdWuWrcrdD56rO2ks5tUzn5gaJpZM4R1HA3.

[304NotModified]

I gonna close this one, as the original issue has been resolved in rc5. Feel free to open new issues

[304NotModified]

I've updated, I seem to be hitting an infinite loop in TemplateEnumerator.MoveNext(). Guessing it is my problem, will debug deeper shortly, but if you're curious you can grab the branch from the PR in datalust/nlog-targets-seq#27 :-)

@nblumhardt RC6 is now in the build pipeline!

[snakefoot]

I guess if this build is approved for the Seq-target, then we have an official Nlog 4.5 RTM Build.

[304NotModified]

indeed

[304NotModified]

PS it's live now: https://www.nuget.org/packages/NLog/4.5.0-rc06

[nblumhardt]

Awesome! Will try it out this morning and let you know how it goes!

[nblumhardt]

Looking good - tests all pass, data makes it to Seq complete with structured properties :-)

https://www.nuget.org/packages/NLog.Targets.Seq/1.0.0-dev-00036 is our 4.5.0-rc6 compatible package, NuGet is still thinking hard about publishing it so it might take a few more minutes to show up.

Pre-emptive congratulations on the release!