Nlog: missing event-properties fields when logging to network with JsonLayout

[adrianpetcu]

There seems to be an issue when logging to the network target, with JsonLayout. The fields obtained from the event-properties are missing.

Type: Bug
NLog version: 4.4.12
Platform: .Net 4.5

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

<?xml version="1.0" encoding="utf-8" ?>
<!-- Logging works, but dbResponseTime & messagesSentTotal fields are missing-->
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Trace" internalLogFile="NLogTrace.json">
  <targets>
    <target xsi:type="Network" address="tcp://127.0.0.1:1314" name="networkTarget" newLine="true">
      <layout xsi:type="JsonLayout" includeAllProperties="true">
        <attribute name="application" layout="${literal:text=NLogConsole}" />
        <attribute name="timestamp" layout="${date:universalTime=true:format=o}" />
        <attribute name="machineName" layout="${machinename}" />
        <attribute name="environment" layout="${literal:text=DEV}" />
        <attribute name="dbResponseTime" layout="${event-properties:item=dbResponseTime}" encode="false"/>
        <attribute name="messagesSentTotal" layout="${event-properties:item=messagesSentTotal}" encode="false"/>
        <attribute name="module" layout="${literal:text=core}" />
      </layout>
    </target>
  </targets>
  <rules>    
    <logger name="*" minlevel="Info" writeTo="networkTarget"/>      
  </rules>
</nlog>

In case of a BUG:

• What is the current result? The logged result is:

{ application: 'NLogConsole', timestamp: '2018-02-12T09:13:06.8305696Z', machineName: 'LAB-01', environment: 'DEV', module: 'core' }

• What is the expected result? The result should also contain the fields from the event properties (in this case, dbResponseTime and messagesSentTotal):

{ application: 'NLogConsole', timestamp: '2018-02-12T09:12:42.7514494Z', machineName: 'LAB-01', environment: 'DEV', dbResponseTime: 50, messagesSentTotal: 100, module: 'core' }

• Are there any work arounds? Yes, add also a file target with exactly the same layout, and log to both the file target and network target. In this case, the network target message will contain the missing fields:

<?xml version="1.0" encoding="utf-8" ?>
<!-- With this setup, the full message is logged to both file and network-->
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Trace" internalLogFile="NLogTrace.json">
  <targets>
    <target xsi:type="File" name="fileTarget"
     fileName="Info.${shortdate}.json"
     archiveFileName="Info.{#}.json"
     archiveNumbering="DateAndSequence"
     archiveAboveSize="33554432"
     archiveDateFormat="yyyy-MM-dd">
      <layout xsi:type="JsonLayout" includeAllProperties="true">
        <attribute name="application" layout="${literal:text=NLogConsole}" />
        <attribute name="timestamp" layout="${date:universalTime=true:format=o}" />
        <attribute name="machineName" layout="${machinename}" />
        <attribute name="environment" layout="${literal:text=DEV}" />
        <attribute name="dbResponseTime" layout="${event-properties:item=dbResponseTime}" encode="false"/>
        <attribute name="messagesSentTotal" layout="${event-properties:item=messagesSentTotal}" encode="false"/>
        <attribute name="module" layout="${literal:text=core}" />
      </layout>
    </target>

    <target xsi:type="Network" address="tcp://127.0.0.1:1314" name="networkTarget" newLine="true">
      <layout xsi:type="JsonLayout" includeAllProperties="true">
        <attribute name="application" layout="${literal:text=NLogConsole}" />
        <attribute name="timestamp" layout="${date:universalTime=true:format=o}" />
        <attribute name="machineName" layout="${machinename}" />
        <attribute name="environment" layout="${literal:text=DEV}" />
        <attribute name="dbResponseTime" layout="${event-properties:item=dbResponseTime}" encode="false"/>
        <attribute name="messagesSentTotal" layout="${event-properties:item=messagesSentTotal}" encode="false"/>
        <attribute name="module" layout="${literal:text=core}" />
      </layout>
    </target>

  </targets>

  <rules>        
    <logger name="*" minlevel="Info" writeTo="fileTarget,networkTarget"/>      
  </rules>
</nlog>

• Is there a version in which it did worked? I don't know
• Can you help us by writing an unit test? Added this repo for tests: https://github.com/adrianpetcu/nlog-networktarget-issue

[304NotModified]

Thanks for the report. Any change to test it with nlog 4.5 rc?

[adrianpetcu]

I tested with 4.5.0-rc05, the issue still exists.

[304NotModified]

OK thanks, if you have time to create an unit test, that would really boost the fix

[304NotModified]

snakefoot commented 6 days ago
...

Regarding the issue with missing LogEvent Properties when using NetworkTarget alone, then I think there is missing a call to Target.MergeEventProperties in NetworkTarget. My pending PR for logger callsite makes MergeLogEventProperties obsolete…

https://github.com/NLog/NLog/issues/2557#issuecomment-365224646

[adrianpetcu]

The problem only occurs when using Info/Debug/Error methods of the Logger, when using the Log method everything works fine.

      LogEventInfo eventInfo = new LogEventInfo(LogLevel.Error, "InfoLogger", "Test");
        eventInfo.Properties.Add("dbResponseTime", 50);
        eventInfo.Properties.Add("messagesSentTotal", 100);
        logger.Log(eventInfo);  //all properties present
        logger.Info(eventInfo); //dbResponseTime &&  messagesSentTotal missing

[snakefoot]

@adrianpetcu Yes calling Log() will also work. Also think wrapping the network-target within an AsyncWrapper will also fix the problem. Have created a PR #2586 that will resolve the issue.

[snakefoot]

@adrianpetcu NLog 4.5.4 has been released that fixes the issue: https://www.nuget.org/packages/NLog/ (includes the fix mentioned about)

[adrianpetcu]

Thanks, works perfectly now!