- Notifications
You must be signed in to change notification settings - Fork1.4k
How to use structured logging
NLog 4.5 introduces structured logging - also called semantic logging. This document describes how to use structural logging. The implementation in NLog supports the message templates syntax, so it is recommended to check:https://messagetemplates.org/
Structured logging makes it easier to store and query log-events, as the logevent message-template and message-parameters are preserved, instead of just transforming them into a formatted message.
The normal .NETstring.Format(...) will only accept input strings like this:
logger.Info("Logon by user:{0} from ip_address:{1}","Kenny","127.0.0.1");logger.Debug("Shopitem:{0} added to basket by user:{1}","Jacket","Kenny");
When storing these log-events in a database (or somewhere else), then it can be difficult to query all actions performed by a certain user. Also it could be hard to group similar events.
The workaround would then be to perform RegEx-queries to recognize logevent messages and convert them into a more structured format, and register which parameter index is the user. The RegEx might even have to extract the needed details from the formatted message, making it even more fragile. Maintaining these RegEx-queries can become rather cumbersome.
Instead of using the message-template to group LogEvents, then Microsoft recommends using EventId / EventName to make it easy to identify LogEvent patterns. This gives more freedom to change the message-template if needed, and the EventName provides a simple human-readable-identifier.
Further history:messagetemplates.org
NLog has always supported log-event metadata calledevent-properties, but it requires a little effort to generate a log-event with properties. See also theFluent-Logger-API
NLog 4.5 makes it possible to capture log-event-properties from the log-message-template, so they can be easily processed by the NLog destination target:
logger.Info("Logon by {user} from {ip_address}","Kenny","127.0.0.1");// Logon by "Kenny" from "127.0.0.1"logger.Debug("{shopitem} added to basket by {user}",new{Id=6,Name="Jacket",Color="Orange"},"Kenny");
Any NLog destination target that is able to handle log-event-properties will automatically experience the benefit of doing structured logging.
The formatting of message depends on the datatype of the parameters.
Example:
logger.Info("Order {orderid} created for {user}",42,"Kenny");
Will be formatted as (Before NLog v6 strings would had quotes):
Order 42 created for Kenny
The formatting is controlled by the datatype of the parameter:
- null: printed as
NULL - list/ienumerable/array:
item1, item2 - dictionary:
key1=value1, key2=value2 - objects:
ToString()
It's possible to control formatting by preceding@ or$:
@will format the object as JSON$forcesToString()
Objecto=null;logger.Info("Test {value1}",o);// null case. Result: Test NULLlogger.Info("Test {value1}",newDateTime(2018,03,25));// datetime case. Result: Test 25-3-2018 00:00:00 (locale ToString)logger.Info("Test {value1}",newList<string>{"a","b"});// list of strings. Result: Test a, blogger.Info("Test {value1}",new[]{"a","b"});// array. Result: Test a, blogger.Info("Test {value1}",newDictionary<string,int>{{"key1",1},{"key2",2}});// dict. Result: Test key1=1, key2=2varorder=newOrder{OrderId=2,Status=OrderStatus.Processing};logger.Info("Test {value1}",order);// object Result: Test MyProgram.Program+Orderlogger.Info("Test {@value1}",order);// object Result: Test {"OrderId":2, "Status":"Processing"}logger.Info("Test {value1}",new{OrderId=2,Status="Processing"});// anonymous object. Result: Test { OrderId = 2, Status = Processing }logger.Info("Test {@value1}",new{OrderId=2,Status="Processing"});// anonymous object. Result: Test {"OrderId":2, "Status":"Processing"}
When formatting the log message, then it will automatically serialize the parameters (seeFormatting of the message). It is also possible to configure NLog Layout to serialize the individual properties. This can be done by using${event-properties} or${all-event-properties}, for example:
<targetxsi:type="File"name="jsonFile"fileName="c:\temp\nlog-json-${shortdate}.log"> <layout>${longdate}|${level}|${logger}|${message}|${all-event-properties}{exception:format=tostring}</layout> </target>
NLog Layouts with optionincludeEventProperties="true" (Before NLog 5.0 it wasincludeAllProperties="true") will output captured properties from structured logging:
It can be configured like this:
<targetxsi:type="File"name="jsonFile"fileName="c:\temp\nlog-json-${shortdate}.log"> <layoutxsi:type="JsonLayout"includeEventProperties="true"> <attributename="time"layout="${longdate}" /> <attributename="level"layout="${level:upperCase=true}"/> <attributename="message"layout="${message}" /> </layout> </target>
NLog 4.5 adds support for rendering the raw message-template, instead of just the formatted message:
NLog 4.5 extends the following NLog LayoutRenderers with support for serializing with property reflection into JSON whenformat="@"
- ${event-properties}
- ${exception}
- ${gdc} - Global Context
- ${scopeproperty} - Thread Context (Before NLog 5.0 it was${mdc} +${mdlc})
In code you can useLogEventInfo.Properties. If having special interest in format-options for the captured parameters then one can useLogEventInfo.MessageTemplateParameters
Any NLog destination target that handlesevent-properties will be able to take advantage of structured logging. Many targets already has support for the optionincludeEventProperties="true", that comes automatically when inheriting fromTargetWithContext.
NLog Targets with supports for NLog Layout as payload will automatically support structured logging:
- NLogViewer Target makes use ofLog4JXml Layout.
- WebService Target can perform JSON-post withJson Layout.
- Network Target can publish bothJson Layout andXml Layout to any TCP/UDP-endpoint.
- Database Target can write to an XML column usingXml Layout
There are already many custom NLog targets that provide the ability to store log-events in central storage, and allow a Web-Application to query the log-events along with their event-properties. These targets will automatically benefit from structured logging, and allow the Web-Application to perform effective queries.
NLog 4.6.3 allows you to navigate into a complex object and extract a single property. Ex:
logger.Debug("{shopitem} added to basket by {user}",new{Id=6,Name="Jacket",Color="Orange"},"Kenny");
Then one can extract specific details fromshopItem-property:
<layoutxsi:type="JsonLayout"> <attributename="shopitemId"layout="${event-properties:shopitem:objectPath=Id}" /> </layout>
To avoid object reflection for a custom type, then just implement theIFormattable-interface, and NLog will call ToString() instead of doing reflection of properties.
NLog 4.7 allows you to transform large (or dangerous) objects into a more reduced/safe object:
LogManager.Setup().SetupSerialization(s=>s.RegisterObjectTransformation<System.Net.WebException>(ex=>new{Type=ex.GetType().ToString(),Message=ex.Message,StackTrace=ex.StackTrace,Source=ex.Source,InnerException=ex.InnerException,Status=ex.Status,Response=ex.Response.ToString(),// Call your custom method to render stream as string}));
This can also be used to output object-fields, as the NLog Object Reflection only sees object-properties. By transforming into an Anonymous Type, and assigning the wanted object-fields to named properties.
If more dynamic reflection is required, then one can also just return aDictionary<string, object> instead of returning an Anonymous Type (The performance hit is a little higher).
Note when making an override for an object-type, then the returned object-type must be of a different object-type (Ex. anonymous object). Because NLog caches the reflection of the return object-type, and afterwards NLog skips checking for transformation for already cached object-types.
Create a new class thatNLog.IValueFormatter and set NLog.Config.ConfigurationItemFactory.Default.ValueFormatter
You can override the builtin NLog JSON converter with a different implementation.
You need a customNLog.IJsonConverter and setNLog.Config.ConfigurationItemFactory.Default.JsonConverter
Example of using JSON.NET that supports JSON.NET object annotations like[JsonIgnore]:
internalclassJsonNetSerializer:NLog.IJsonConverter{readonlyJsonSerializerSettings_settings;publicJsonNetSerializer(){_settings=newJsonSerializerSettings{Formatting=Formatting.Indented,ReferenceLoopHandling=ReferenceLoopHandling.Ignore};}/// <summary>Serialization of an object into JSON format.</summary>/// <param name="value">The object to serialize to JSON.</param>/// <param name="builder">Output destination.</param>/// <returns>Serialize succeeded (true/false)</returns>publicboolSerializeObject(objectvalue,StringBuilderbuilder){try{varjsonSerializer=JsonSerializer.CreateDefault(_settings);varsw=newSystem.IO.StringWriter(builder,System.Globalization.CultureInfo.InvariantCulture);using(varjsonWriter=newJsonTextWriter(sw)){jsonWriter.Formatting=jsonSerializer.Formatting;jsonSerializer.Serialize(jsonWriter,value,null);}}catch(Exceptione){NLog.Common.InternalLogger.Error(e,"Error when custom JSON serialization");returnfalse;}returntrue;}}
e.g. logging"Hello {0} with {Message}"
For backward compatibility (and performance), then NLog will by default skip full parsing if it detects the first parameter as being positional index. This will ensure repeated positional-placeholders supported bystring.Format will continue to work:
string.Format("{1}{0}{2}{0}",Environment.NewLine,"Hello","World");
WhenparseMessageTemplates='true' then NLog will always parse all parameters, and if one is non-numeric, then all the parameters will be treated as structured parameters. Mixing and numeric and structured parameters is not recommended, as it hurts performance (backtrack) and numeric parameters are most of the time not so descriptive.
The Names of the parameters should be unique
e.g.Order {orderId}
Use${message:raw=true}
NLog will by default attempt to parse log-events as structured log-events. This gives a minor overhead, that will not be noticable by most.
It is possible to disable this behavior, telling NLog it should not attempt to parse log-events as structured log-events, with this xml-setting:
<nlogparseMessageTemplates="false"> ...</nlog>
NLog v6 removed quotes for strings to behave like Microsoft Extensions Logging. To revert to old behavior with string-quotes:
LogManager.Setup().SetupSerialization(s=>s.RegisterValueFormatterWithStringQuotes());
Alternative one can use@ to add string-quotes:
Logger.Info("Hello {@World}","Earth");// Outputs Hello "Earth"
-Troubleshooting Guide - See available NLog Targets and Layouts:https://nlog-project.org/config
- All targets, layouts and layout renderers
Popular: - Using NLog with NLog.config
- Using NLog with appsettings.json