Nlog: Add structural logging (proposals/discussion/prototypes)

[304NotModified]

Add structural logging support like Serilog. This is a call for proposals/discussion/prototypes

Why?

• It's used in ASPNET5 logging / DNX logging of Microsoft
• It works well with Common Logging
• It seems popular
• I like it :)

We need a prototype on this.

Things to check:

• It should be optional (config setting in XML and LogConfiguration) - one global setting is good enough for now.
• We should check which syntax Microsoft is using
• We should consider if Serillog's syntax is the best
• We must list the syntax we will implement (here)
• The syntax should be future proof (extenable, interpolated strings)
• We should cache parsing the Layouts
• Proposal to write the arguments to "event properties"

See also http://nlog.userecho.com/topics/21-make-structural-logging-possible/

[304NotModified]

Serilog syntax:

• {propertyname}
• {propertyname:format}
• escape { by {{ (like string.format)
• prefixes: @ and $
• > If any of the property names are non-numeric, then all property names will be matched from left-to-right with the log method's parameters

[304NotModified]

Microsoft's logging in A,SP.NET core (aka ASP.NET 5) / DNX

• Code: LogValuesFormatter, but undocumented
• Docs LogValuesFormatter
• logging fundamentals docs

[304NotModified]

Some thoughts:

• No need for format or destructors in NLog, we have layout renderers?
• sending an object to a log method and take its properties sounds nice, but check the performance. We need dynamic for performance?

[nblumhardt]

Personally I think this would be awesome :-) A couple of other impls: https://github.com/adamchester/messagetemplates, https://github.com/logary/logary/pull/90. Because it's now supported in a few places some have adopted the term "message templates" rather than Serilog-like to describe the named-holes/capturing techinque.

Regarding your note above, Serilog ended up with the design it uses here because in Serilog, the "serialization" can be offloaded for async/background processing. Snapshotting ("destructuring") not-known-to-be-immutable values at the point of logging prevents threading issues in this case.

Looking back, a viable and perhaps simpler alternative would be applying "formatting" at the point the log event is captured (even if just into JSON) - I guess that's what you're referring to by "formatters"? Really interested to see what direction the design takes, anyway. It's a fun problem space :-)

[304NotModified]

Thanks @nblumhardt, I wasn't aware of the "message templates" name.

Do you have any thoughts on how to combine the current templating (the layout renderers), with the message templates?

Snapshotting ("destructuring") not-known-to-be-immutable values at the point of logging prevents threading issues in this case.

That's is really good point here.

Looking back, a viable and perhaps simpler alternative would be applying "formatting" at the point the log event is captured (even if just into JSON) "?

I don't think that both solutions are difficult :) The most difficult would be the design IMO.

I guess that's what you're referring to by "formatters

I meant JSON, XML etc.

---

Just to get started, I will think out loud and post my first proposal:

Proposal 1:

a. Do use the Serilog syntax and write all info to ${message}
b. Try if the "MessageTemplates" suits well (NB: It seems alpha now)
c. Create a separate extensions to NLog.
d. Add "Destructed" objects to the event properties - you can use them later and convert them to JSON/XML or process them in C#
e. Also "Destructed" objects will be "Destructed" to the message as JSON
f. Make structural logging optional, as an setting on global level.

Thoughts:

• Not sure if this is the golden combination between layout renderers and message templates.
• Maybe separate d and e? Then we need more syntax then Serilog's?

[nblumhardt]

I'm not super-experienced with NLog so I may miss the mark with a few things, but I think working through the compatibility goals for the feature will help shake the design out a lot.

f) seems to buy some compatibility leeway, but unless structured data support can be depended upon _libraries_ won't be able to use it so they'll either need to restrict themselves to {0}, {1} placeholders, or use an intermediary like LibLog to do the transformation.

Let's assume that having {named} placeholders in LogEventInfo.Message would cause unacceptably widespread breakage. Would adding MessageTemplate alongside it, and having Message perform the translation lazily (back to {0}, {1}) be an acceptable cost?

Because message templates use positional binding, a template translated back into a .NET format string this way would still match up perfectly with LogEventInfo.Parameters.

At that point, so long as the named properties are added into LogEventInfo.Properties everything seems pretty coherent.

When the caller does pass numeric argument names, either because the programmer preferred classic style or because the caller is existing code, adding properties named "0", "1" etc. to Properties has worked well for Serilog - though they're not as pleasing to read, they do still provide some nice structured data handling options "for free".

(The Seq client for NLog actually uses LogEventInfo.Parameters to emulate this today: https://github.com/continuousit/seq-client/blob/master/src/Seq.Client.NLog/Client/NLog/LogEventInfoFormatter.cs#L118.)

Hope this helps, keen to hear how your thinking's evolved in the week since the last update... :-)

[304NotModified]

Thanks @nblumhardt!

I will try to work on a prototype upcoming week

[304NotModified]

The only reason to make it optional is for performance. If you never use it, why spending time on parsing more complex stuff. I'm pretty sure that the string.format is fully optimised, although I have to check the implementation.

But it is better to enable it by default.

[304NotModified]

First .NET core RC2 before this

[304NotModified]

Looking at this.

• https://github.com/adamchester/messagetemplates

Unfortunately, it does not have .NET 3.5 support (NLog does), it isn't RTM yet and we can't include it as source IMO (Apache license, NLog has BSD)

Looking further, or we need or own implementation

[adamchester]

@304NotModified added net35 now

Regarding RTM, I think we could soon if you wanted to use it.

Regarding source license if you wanted to avoid a dependency, it's mostly extracted from serilog, so I'll leave that for @nblumhardt.

[304NotModified]

@adamchester thanks!

[304NotModified]

PS see https://github.com/serilog/serilog/issues/822

If this is not possible, I will probable write my own implementation, which will be BSD licensed. Of course using the same specs.

[jods4]

@304NotModified :+1: I am so excited for this to happen!
I was looking into Serilog to get structured logging into Seq... but NLog is currently a lot better. 😉
I think with ASP.NET Core adopting structured logging it will become increasingly popular.

[304NotModified]

Good to hear!

Currently I'm working on the parser. See https://github.com/NLog/yamtp/pull/1 (basic start)

[304NotModified]

This is still WIP.

[biiiipy]

Nice to hear! Is there some rough estimate of potential release? Waiting on this to land so I can move from Serilog to NLog.

[304NotModified]

It's not fully clear, but I expect a beta within 6 weeks. After that it could go fast. Right now I'm very busy outside NLog and we need a lot of test cases so we're sure that's it's compatible with NLog and serilog.

If you think you could help us with that, please do :)

[304NotModified]

Unfortunately needed some more time! Any way, the first alpha is now online!

All tests are succeeding for .NET 3.5/4/4.5! 😄

https://www.nuget.org/packages/NLog/4.5.0-alpha01

the todo list is in the PR: https://github.com/NLog/NLog/pull/1951

[biiiipy]

Fantastic!

[nblumhardt]

@304NotModified I have some time blocked out today to test this with Seq - any tips for writing a "gold standard" provider? There's one for older NLog versions here, but since this is such a landmark release I'm interested in updating it to maximise flexibility/perf with the new features. Any tips/examples/pointers I can keep in mind? Cheers!

[304NotModified]

@nblumhardt since NLog 4.4.2 there is a better way to render logeventinfos. See

https://github.com/NLog/NLog/blob/3cbb23278b8ddb68e67f1defd796fa7d5812b331/src/NLog/Targets/Target.cs#L676

Example https://github.com/NLog/NLog/pull/1910/files

Highly related https://github.com/NLog/NLog/pull/1799

Ps on mobile now.

[304NotModified]

@nblumhardt PS, https://github.com/datalust/seq-client/blob/master/src/Seq.Client.NLog/Client/NLog/LogEventInfoFormatter.cs#L146 SanitizeKey

Could be more efficient I think. No need to always allocate a new string and the original string have to be scanned at most once.

[304NotModified]

@nblumhardt any I think WriteAsyncThreadSafe is interesting (target), see https://github.com/NLog/NLog/pull/1700

For optimal performance I would replace the default serializer, see https://github.com/NLog/NLog/pull/1951#issuecomment-279216903

Maybe is pinning a NLog version the safe option (in nuspec), as I think so breaking changes could be needed.

Last but not last, happy profiling(!) and please report back to us if you found some performance issues in NLog components :)

[nblumhardt]

@304NotModified thanks! Will do.

[aKabirKhan]

Any Update on this and where I can get the 4.5 latest Alpha ?

[304NotModified]

We're working on it. We are currently working on an improved json serializer, which we need for this.

[304NotModified]

I'm thinking to only parse the structured template when the string is prefixed by a @.

So:

c# "Hello {0}" // (string.format) "@Hello {A}" //(structured logging) "Hello {A}" //(Exception by string.format - backwards comp)

This for performance and backwards compatibility, any thoughts?

@snakefoot

[biiiipy]

Well, that looks cumbersome and error prone... Maybe:

• This alternatively could be done with a global switch to opt-in for structural logging?
  
  
  
  • And maybe by using "@" you opt-out of structured logging where (if) it's needed
  
  
• Also, if the view is that structured logging is a better default, then maybe this could be an opt-out switch?
  It shouldn't be a huge breaking change to set a switch if you update to a newer version.

[304NotModified]

A global switch isn't really working as other (external) components could use structural logging.

The structural logging is always taking more allocations/memory and CPU. I think the difference is small, but it's there.

[snakefoot]

I think a global switch to optin for full token scan. It is a good idea with using first character to signal special string formatting, but nlog is not first on the scene. Maybe if there are args then scan for first curlybracket and then check next is digit, then it will use standard string format. Else perform full token scan, where optin means force full token scan always without prescan.

Can probably also create a full token scanner and formatter that only allocates the formatted string (and the token list when non positional)

Sent from my Samsung device

-------- Original message --------
From: Julian Verdurmen [e-mail]
Date: 24/06/2017 16:48 (GMT+01:00)
To: NLog/NLog [e-mail]
Cc: Rolf Kristensen [e-mail], Mention [e-mail]
Subject: Re: [NLog/NLog] Add structural logging (proposals/discussion/prototypes) (#1376)

A global switch isn't really working as other (external) components could use structural logging.

The structural logging is always taking more allocations/memory and CPU. I think the difference is small, but it's there.

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

[biiiipy]

as other (external) components could use structural logging.

In that case of course the user should not use the global switch and use prefixed "@" where/if it's needed. For a lot of use cases I think this is not a problem. It's backwards compatible but also a lot more usable going forward.

[nblumhardt]

Is the goal to move NLog forwards as a structured logging library, though? If so, I think requiring an opt-in will keep NLog feeling like a text logger with structured data bolted on. Opt-in features usually suffer a lack of attention and consideration over the long term.

A global opt-out could be a better approach. The (small?) percentage of users that a) don't want structured logging, and b) have extreme logging performance requirements, could seek out how to set this flag as an optimization.

[304NotModified]

Thanks for the input guys!

The @ prefix is off the table, will first make it opt-out and benchmark the performance. (could use some help on this ;))

I think it's acceptable to have a small memory increase with NLog 4.5, with the global switch.

[biiiipy]

If it suits better you can introduce structured logging in NLog 4.5 with global switch off by default and in NLog 5 switch it on by default.

[304NotModified]

If it suits better you can introduce structured logging in NLog 4.5 with global switch off by default and in NLog 5 switch it on by default.

Good idea! Will think about it, depending on the benchmark

[tylerohlsen]

Any ETA on when this feature will be production ready?

[304NotModified]

1-2 months. Maybe earlier if we get more test feedback. Will try to create a beta this weekend.

[tylerohlsen]

Sorry to be a bother, but will a beta be coming out soon with this feature?

[snakefoot]

@tylerohlsen We have the PRs ready:

2263 (NetStandard 2.0 Support. Huge task that will conflict with all other PRs - Now Committed)

2262 (Interface decision. Discussion time - Now Committed)

2208 (Message Parser. Performance - Now Committed)

Just need to have them approved and committed.

[nblumhardt]

Itching to update _NLog.Targets.Seq_ to support NLog 4.5-beta01 :-) I think we're blocked as the earlier _NLog.StructuredEvents_ package doesn't seem to work against the latest version. (If there's some way of making this work in the meantime, any pointers would be appreciated.) Thanks!

[snakefoot]

@nblumhardt I think we're blocked as the earlier NLog.StructuredEvents package doesn't seem to work against the latest version

Yes it is a little confusing that the main-branch has moved forward to new version, without having merged in the changes needed for structured logging (see my post above about pending PRs). But the version upgrade is also because it now supports NetStandard 2.0

[304NotModified]

Structured logging is back!

https://www.nuget.org/packages/NLog/4.5.0-beta04
!

great work @snakefoot !!

[304NotModified]

please feedback here!

https://github.com/NLog/NLog/issues/2332

thanks in advance!