Nlog: QUESTION: ${xml-encode} layout renderer does not serialize all event properties to XML

[scooternva]

• NLog version: 4.7.2
• No config file (doing configuration in C#)
• Expected result: structured event properties rendered as XML with the ${xml-encode} layout renderer
• Actual result: heartbreak, agita, and no data for the properties (or only the fully-qualified name of the event properties class), and definitely never XML

Here's a simplified version of the C# class that I want to be serialized to XML by the logger:

[Serializable]
public class TaskState
{
    public bool IsOK { get; set; }
    public string Errors { get; set; }

    /// <summary>
    /// Default parameterless constructor
    /// </summary>
    public TaskState() { }
}

Usage example:

var taskState = new TaskState()
{
    IsOK = false,
    Errors = "Unable to connect."
};

Logger.Warn("Workflow task aborted with status: {TaskState}", taskState);

Configuration of the layout in an NLogs.Targets.FileTarget:

var fileTarget = new FileTarget()
{
    Layout="${longdate}|${level:uppercase=true}|${message}|${xml-encode:inner:${all-event-properties}}",
    // Init other properties of FileTarget...
};

What I expected to get in the log entry (using the C# example above):

2020-06-24 23:35:55.8851|INFO|Workflow task aborted with status: MyNameSpace.TaskState|<TaskState><IsOK>false</IsOK><Errors>Unable to connect.</Errors></TaskState>

What I actually got:

2020-06-24 23:35:55.8851|INFO|Workflow task aborted with status: MyNameSpace.TaskState|TaskState=MyNameSpace.TaskState

The ${message} layout gets formatted as I expected, since I read that objects get serialized with the default ToString() method when using that layout. But no matter what combination of settings I try fo the ${xml-encode} layout renderer, I either get empty string or the fully-qualified class name for the TaskState object. I definitely never get a chunk of XML.

I'm getting the sense that what I'm trying to achieve is not built into NLog, or at the very least is not possible to do strictly in code, but before I dive in and spend time creating a custom layout renderer I thought I'd ask if I was _(probably, hopefully!)_ doing something fundamentally wrong and easily fixed. (BTW, in case you're wondering why I'm doing this in code vs. a config file, it's because I'm encapsulating NLog configuration in a shared class library to enforce logging standards across a large project.)

Many thanks in advance for any advice that will be gratefully appreciated. NLog is crazy fast and so much more flexible than log4Net, but this one thing that was so easy to do in log4Net is absolutely baffling me in NLog.

[welcome[bot]]

Hi! Thanks for opening your first issue here! Please make sure to follow the issue template - so we could help you better!

[snakefoot]

If you read the documentation for ${xml-encode} then you will see takes a string and escapes characters (But it does not insert xml-tags):

https://github.com/nlog/NLog/wiki/Xml-Encode-Layout-Renderer

Maybe XmlLayout is what you are looking for:

https://github.com/NLog/NLog/wiki/XmlLayout

You can concat the output from different Layout using CompoundLayout:

https://github.com/NLog/NLog/wiki/CompoundLayout

[scooternva]

Hi @snakefoot, thanks for the reply. That makes perfect sense what you’re saying, and now that I look at ${xml-encode} again its purpose is much clearer.

Unfortunately XmlLayout doesn’t seem to be the right fit either; I only want to serialize to XML the event properties, not render the entire log document in XML. (One of my targets is DatabaseTarget, and the reason I was looking to put the event properties into XML is so they could be stored in an XML column in SQL Server.) It looks like I’m going to be diving into custom layout renderers after all. Thanks!

[snakefoot]

Curious what you are missing for using XmlLayout together with DatabaseTarget?

<target name="db" xsi:type="Database" connectionstring="..." >
  <commandtext>INSERT INTO FooBar VALUES(@ts, @lvl, @msg, @props)</commandtext>
  <parameter name="@ts" layout="${date}" dbType="SqlDbType.DateTime2" />
  <parameter name="@lvl" layout="${level}" dbType="DbType.Int32" />
  <parameter name="@msg" layout="${message}" dbType="SqlDbType.VarChar" size="-1" parameterType="String" />
  <parameter name="@props" dbType="SqlDbType.Xml" size="-1">
     <layout type="xmllayout" includeAllProperties="true" />
  </parameter>
</target>

[repo-ranger[bot]]

Please add the requested info, so we could help you better! (This issue will be closed in 7 days)

[scooternva]

Hi @snakefoot ... What I was apparently missing was the understanding that XmlLayout is not part of the core NLog package. When I downloaded NLog.Xml and changed the relevant DatabaseParameterInfo.Layout property to "${xml:${all-event-properties}}", everything suddenly roared to life; all properties are now being serialized to XML in the PROPERTIES column:

namespace ExampleService
{
    static class Program
    {
        private static Logger MyLogger { get; set; }

        /// <summary>
        /// The main entry point for the application.
        /// </summary>
        static void Main()
        {
            LogManager.ThrowExceptions = true;
            LogManager.ThrowConfigExceptions = true;

            // Dynamically configure NLog:
            var config = new NLog.Config.LoggingConfiguration();

            /**** SQL SERVER ****/

            DatabaseTarget dbTarget = new DatabaseTarget()
            {
                DBProvider = "mssql",
                ConnectionStringName = "ExampleService.Properties.Settings.SystemLogConnection",
                IsolationLevel = IsolationLevel.ReadCommitted,
                CommandType = CommandType.StoredProcedure,
                CommandText = "[dbo].[SYSTEM_LOG_INSERT_PROC]"
            };

            DatabaseParameterInfo param;

            param = new DatabaseParameterInfo()
            {
                Name = "@MACHINE_NAME",
                Layout = "${MachineName}",
                DbType = SqlDbType.NVarChar.ToString(),
                Size = 200
            };
            dbTarget.Parameters.Add(param);

            param = new DatabaseParameterInfo()
            {
                Name = "@EVENT_DATE",
                Layout = "${date}",
                DbType = SqlDbType.DateTime2.ToString(),
                Size = 7
            };
            dbTarget.Parameters.Add(param);

            param = new DatabaseParameterInfo()
            {
                Name = "@LOG_LEVEL",
                Layout = "${level}",
                DbType = SqlDbType.VarChar.ToString(),
                Size = 5
            };
            dbTarget.Parameters.Add(param);

            param = new DatabaseParameterInfo()
            {
                Name = "@MESSAGE",
                Layout = "${message}",
                DbType = SqlDbType.NVarChar.ToString(),
                Size = -1
            };
            dbTarget.Parameters.Add(param);

            param = new DatabaseParameterInfo()
            {
                Name = "@LOGGER",
                Layout = "${logger}",
                DbType = SqlDbType.NVarChar.ToString(),
                Size = 300
            };
            dbTarget.Parameters.Add(param);

            param = new DatabaseParameterInfo()
            {
                Name = "@PROPERTIES",
                Layout = "${xml:${all-event-properties}}",   // <-- AHA!!!
                DbType = SqlDbType.Xml.ToString(),
                Size = -1
            };
            dbTarget.Parameters.Add(param);

            param = new DatabaseParameterInfo()
            {
                Name = "@CALL_SITE",
                Layout = "${callsite}",
                DbType = SqlDbType.NVarChar.ToString(),
                Size = 300
            };
            dbTarget.Parameters.Add(param);

            param = new DatabaseParameterInfo()
            {
                Name = "@EXCEPTION",
                Layout = "${exception:tostring}",
                DbType = SqlDbType.NVarChar.ToString(),
                Size = -1
            };
            dbTarget.Parameters.Add(param);

            var asyncDbWrapper = new AsyncTargetWrapper()
            {
                Name = "AsyncDbWrapper",
                BatchSize = 25,
                OverflowAction = AsyncTargetWrapperOverflowAction.Block,
                WrappedTarget = dbTarget
            };

            /******* FILE LOGGING *******/

            var fileTarget = new FileTarget()
            {
                ArchiveAboveSize = 10000000,
                ArchiveDateFormat = "yyyy-MM-dd",
                ArchiveEvery = NLog.Targets.FileArchivePeriod.Day,
                ArchiveFileKind = NLog.Targets.FilePathKind.Relative,
                ArchiveNumbering = NLog.Targets.ArchiveNumberingMode.DateAndSequence,
                AutoFlush = false,
                BufferSize = 1048576,
                ConcurrentWrites = true,
                CreateDirs = true,
                EnableArchiveFileCompression = true,
                FileNameKind = NLog.Targets.FilePathKind.Relative,
                Encoding = Encoding.UTF8,
                KeepFileOpen = true,
                EnableFileDelete = false,
                FileName = "App_Data/log.txt",
                Name = "SystemLogFileLogger",
                OpenFileCacheTimeout = 30,
                ReplaceFileContentsOnEachWrite = false,
                // This is working too, although I'm going to use JSON in the text files...
                Layout = "${longdate}|${level:uppercase=true}|${message}|${xml:${all-event-properties}}" 
            };

            var asyncFileWrapper = new AsyncTargetWrapper()
            {
                Name = "AsyncFileWrapper",
                BatchSize = 25,
                OverflowAction = AsyncTargetWrapperOverflowAction.Block,
                WrappedTarget = fileTarget
            };

            // Add the asynchronous wrappers to the configuration:
            config.AddRule(LogLevel.Info, LogLevel.Fatal, asyncDbWrapper);
            config.AddRule(LogLevel.Debug, LogLevel.Fatal, asyncFileWrapper);

            // Apply config           
            LogManager.Configuration = config;

            // Hmm... the GDC and MDLC are not showing up in the XML:
            GlobalDiagnosticsContext.Set("GDCKey", "ABCDEFG");
            MappedDiagnosticsLogicalContext.Set("MDLCKey", 123456);

            // But the WithPropertyKey property *is* showing up in the <Properties> element:
            MyLogger = LogManager.GetCurrentClassLogger().WithProperty("WithPropertyKey", 987654);

            try
            {
                // Throw an exception to see what gets logged:
                throw new Exception("Eeek! A mouse!");
            }
            catch (Exception e)
            {
                MyLogger.Error(e, "Bad juju!");
            }

            // Force a flush to take a peek at what's being logged:
            MyLogger.Factory.Flush();

The above configuration yields the following output in the [dbo].[SYSTEM_LOG].[PROPERTIES] column (and something similar looking in the text log target):

<LogEvent>
  <SequenceID>3</SequenceID>
  <TimeStamp>2020-06-29T13:45:35.085-04:00</TimeStamp>
  <Level>Error</Level>
  <LoggerName>ExampleService.Program</LoggerName>
  <Message>Bad juju!</Message>
  <Error>
    <TypeName>System.Exception</TypeName>
    <MethodName>Main</MethodName>
    <ModuleName>ExampleService</ModuleName>
    <ModuleVersion>1.0.0.0</ModuleVersion>
    <Message>Eeek! A mouse!</Message>
    <Source>ExampleService</Source>
    <StackTrace>   at ExampleService.Program.Main() in D:\depot\main\ExampleService\Program.cs:line 175</StackTrace>
    <ExceptionText>System.Exception: Eeek! A mouse!
   at ExampleService.Program.Main() in D:\depot\main\ExampleService\Program.cs:line 175</ExceptionText>
  </Error>
  <StackTrace>   at NLog.LoggerImpl.CaptureCallSiteInfo(LogFactory factory, Type loggerType, LogEventInfo logEvent, StackTraceUsage stackTraceUsage)
   at NLog.LoggerImpl.Write(Type loggerType, TargetWithFilterChain targetsForLevel, LogEventInfo logEvent, LogFactory factory)
   at NLog.Logger.WriteToTargets(LogEventInfo logEvent, TargetWithFilterChain targetsForLevel)
   at NLog.Logger.WriteToTargets(LogLevel level, Exception ex, String message, Object[] args)
   at NLog.Logger.Error(Exception exception, String message)
   at ExampleService.Program.Main()
</StackTrace>
  <Properties>
    <Property>
      <!-- Why is WithProperty() showing up but not the GDC and MDLC dictionary entries? -->
      <Name>WithPropertyKey</Name>
      <Value>987654</Value>
    </Property>
  </Properties>
</LogEvent>

So now I just have four relatively minor (I hope) issues to resolve:

1. Obviously the ${xml:${all-event-properties}} layout renderer is repeating information already being rendered elsewhere (level, logger name, message, stack trace, exception). I need to figure out how to make it only serialize only the event properties in <Properties> node, but no matter how I configure the Layout properties of DatabaseParameterInfo and FileTarget, I always seem to get the entire kitchen sink (well, almost everything... see next issue).
2. I can't seem to figure out how to get the GlobalDiagnosticsContext and MappedDiagnosticsLogicalContext dictionaries to serialize in the XmlLayout. I even tried Layout = "${xml:${gdc}}" just to see what would happen, but I still got the same XML (and no GDC dictionary entries). It seems like ${xml} is ignoring any nested inner layout rendrers.
3. Am I mixing up paradigms? WithProperty seems to be thread-specific (and only for the logger that it modifies). Is that roughly equivalent to MDLC? Should I pick one or the other but not both?
4. I need to figure out how to format the XmlLayout output more efficiently. Semantically for my application, it makes more sense that some of the event properties should be serialized as attributes of other XML elements (rather than everything being serialized as XML elements). This is a very minor issue; items 1, 2, and 3 are showstoppers but I can live with everything as an XML element if I can solve the first three.

But the good news here is that at least XML serialization is working! (Sort of.) Thanks!

[snakefoot]

Looks like you have started to use https://www.nuget.org/packages/NLog.Xml, that is external to NLog-core, and is not maintained by the NLog-project.

If you read the documentation, then it says XmlLayout is included in NLog 4.6 (and newer):

https://github.com/NLog/NLog/wiki/XmlLayout

You should just do this (If you want to include MDLC then also add , IncludeMdlc = true):

c# param = new DatabaseParameterInfo() { Name = "@PROPERTIES", Layout = new NLog.Layouts.XmlLayout() { IncludeAllProperties = true }, DbType = SqlDbType.Xml.ToString(), Size = -1 }; dbTarget.Parameters.Add(param);

Logger.WithProperty creates a new Logger-object, that will automatically inject the given property as LogEvent-Property for all the LogEvents it creates. And will be included when IncludeAllProperties = true.

MappedDiagnosticsLogicalContext (MDLC) is a dictionary stored in a AsyncLocal-thread-state. It will travel with the thread-execution-context independent of the individual Logger-objects.

[scooternva]

AHHHHHHH. This is marvelous, and _soooooooo_ much better.

<logevent>
  <!-- My MDLC dictionary entry, yay! (Still no GDC.) -->
  <property key="MDLCKey">123456</property>
  <!-- "Count" is a structured logging property that was specific only to this event -->
  <property key="Count">22222</property>
  <!-- "WithPropertyKey" was logged using WithProperty() -->
  <property key="WithPropertyKey">987654</property>
</logevent>

I was definitely worried about including a package outside of the core NLog system (especially one that seemed to work a bit, er, oddly) so this is great, and exactly what I was looking for. There doesn't seem to be an option for inclusion of GlobalDiagnosticsContext dictionary entries, but I only have one or two of those per application that write to the [dbo].[SYSTEM_LOG] table and I was going to almost certainly log those as separate columns anyway (to aid in searching the log table), so that's nbd.

What kept throwing me was that when you referred to XmlLayout I kept trying to use a _string_ layout renderer property value for DatabaseParameterInfo.Layout. When ${xmllayout} and ${xml-layout} didn't work and I stumbled across the NLog.Xml package that (sort of) worked, I thought I'd finally figured things out. It never occurred to me that the solution was to instantiate a class and assign it to what up until then had always been a string property. But after poking around a bit with the decompiler, I now see how concrete implementations of NLog.Layouts.Layout are able to achieve this witchcraft.

Now that I (finally!) understand how to get started, I can experiment with with how NLog.Layouts.XmlLayout is instantiated and initialized; I should be able to figure out how to customize the appearance a bit more to my needs.

Thank you VERY much @snakefoot. (Quick forum etiquette question: Should I have clicked "Close and comment" since my issues have now been resolved, or is it expected that the person who helped the thread starter be the one to close it?)

[snakefoot]

NLog automatically converts strings into Layout with help from SimpleLayout that parses and recognizes known LayoutRenderers.

But for more complex/structured layouts like XmlLayout, JsonLayout or CsvLayout then one have to "initialize" them using the constructor (when not using NLog.config-file)

If you want to include some hardcoded GDC-variables then you can do this:

c# var xmlLayout = new NLog.Layouts.XmlLayout() { IncludeAllProperties = true }; var xmGdcLayout = new NLog.Layouts.XmlElement("property", "${gdc:GDCKey}"); xmGdcLayout.Attributes.Add(new XmlAttribute("key", "GDCKey"); xmlLayout.Elements.Add(xmGdcLayout);

When you feel that your issue has been resolved/answered, then it is expected that you close the issue yourself.

[scooternva]

Not only did you resolve my issue, you also gave me a leg up on how to control serialization with NLog.Layouts.XmlLayout. Thanks again!