Hello,

We are using NXLog extensively and just recently started seeing some parsing issues, so far specifically on Windows 2012r2 using Windows Event Forwarding, but could be others. It appears to be something with processing self-closed tags at first glance, but I've done a little bit of testing myself and couldn't directly reproduce the problem (so far), so figured I'd come here for guidance. Specific details are included below.

Current Behavior NXLog appears to be improperly parsing empty, self-closed XML tags.

Expected Behavior NXLog properly ignores empty, self-closed XML tags.

NXLog Version: nxlog-ce-2.10.2150

NXLog Configuration File:

##   NXLog configuration file

define ROOT C:\Program Files (x86)\nxlog

define LOGFILE %ROOT%\data\nxlog.log
Moduledir %ROOT%\modules
CacheDir %ROOT%\data
Pidfile %ROOT%\data\nxlog.pid
SpoolDir %ROOT%\data
LogFile %LOGFILE%

# Rotate agent logs on the local system such that only the last 4 files are kept
<Extension fileop>
    Module  xm_fileop

    # Check the size of our log file every hour and rotate if it is larger than 1M
    <Schedule>
        Every  1 hour
        Exec  if (file_size('%LOGFILE%') >= 1M) file_cycle('%LOGFILE%', 4);
    </Schedule>

    # Rotate our log file every week on sunday at midnight
    <Schedule>
        When  @weekly
        Exec  file_cycle('%LOGFILE%', 4);
    </Schedule>
</Extension>

<Extension syslog>
    Module  xm_syslog
</Extension>

<Extension json>
    Module  xm_json
</Extension>

# Agent logs
<Input internal>
    Module  im_internal
</Input>

# OS logs
<Input eventlog>
    Module  im_msvistalog

    # Drop EventID 5156 logs when application name is nxlog.exe
    Exec  if ($SourceName == 'Microsoft-Windows-Security-Auditing')\
      AND ($EventID == 5156)\
      AND ($Application =~ /nxlog.exe$/)\
        drop();
</Input>

<Input forwardedEvents>
    Module im_msvistalog

    Query <QueryList> \
        <Query Id="0"> \
            <Select Path="ForwardedEvents">*</Select>\
        </Query> \
    </QueryList>
</Input>

# SIEM port 3514 is listening for JSON-encoded IETF style syslog messages
# OutputType Syslog_TLS required to enable the octet-framing described in RFC5425
<Output out>
    Module  om_tcp
    Host  XXX.XXX.XXX.XXX
    Port  3514
    OutputType  Syslog_TLS
    Exec  $Message = to_json();

    # Remove param-value pairs from structured data header with names > 32 characters.
    Exec  if ($SourceName == 'Microsoft-Windows-GroupPolicy') {\
                    if ($EventID == 5017) OR ($EventID == 6017) OR ($EventID == 7017)\
                        delete($OperationElaspedTimeInMilliSeconds);\
                    if ($EventID == 5116) OR ($EventID == 6116) OR ($EventID == 7116)\
                        delete($GpsvcInitTimeElapsedInMilliseconds);\
                    if ($EventID == 5126) OR ($EventID == 6126) OR ($EventID == 7126)\
                        delete($GPODownloadTimeElapsedInMilliseconds);\
                    if ($EventID == 5257) OR ($EventID == 6257) OR ($EventID == 7257)\
                        delete($PolicyDownloadTimeElapsedInMilliseconds);\
                    if ($EventID == 5351) OR ($EventID == 6351) OR ($EventID == 7351)\
                        delete($WinlogonReturnTimeElapsedInMilliseconds);\
                }

    Exec     to_syslog_ietf();
</Output>

<Route 1>
    Path  internal, eventlog, forwardedEvents => out
</Route>

Windows Version: Windows 2012r2 (potentially others, but confirmed for sure on this one)

Example Exported XML from EventViewer

<?xml version="1.0" encoding="utf-8" standalone="yes"?>
<Events><Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event' xml:lang='en-US'><System><Provider Name='Microsoft-Windows-Security-Auditing' Guid='{54849625-5478-4994-A5BA-3E3B0328C30D}'/><EventID>4688</EventID><Version>2</Version><Level>0</Level><Task>13312</Task><Opcode>0</Opcode><Keywords>0x8020000000000000</Keywords><TimeCreated SystemTime='2019-10-23T14:01:56.684789600Z'/><EventRecordID>5238702734</EventRecordID><Correlation/><Execution ProcessID='4' ThreadID='3948'/><Channel>Security</Channel><Computer>hostname.domain</Computer><Security/></System><EventData><Data Name='SubjectUserSid'>S-1-5-18</Data><Data Name='SubjectUserName'>workstation$</Data><Data Name='SubjectDomainName'>DOMAIN</Data><Data Name='SubjectLogonId'>0x3e7</Data><Data Name='NewProcessId'>0x1754</Data><Data Name='NewProcessName'>C:\Windows\System32\wbem\WmiApSrv.exe</Data><Data Name='TokenElevationType'>%%1936</Data><Data Name='ProcessId'>0x2f8</Data><Data Name='CommandLine'/><Data Name='TargetUserSid'>S-1-0-0</Data><Data Name='TargetUserName'>-</Data><Data Name='TargetDomainName'>-</Data><Data Name='TargetLogonId'>0x0</Data></EventData><RenderingInfo Culture='en-US'><Message>A new process has been created...</Message><Level>Information</Level><Task>Process Creation</Task><Opcode>Info</Opcode><Channel>Security</Channel><Provider>Microsoft Windows security auditing.</Provider><Keywords><Keyword>Audit Success</Keyword></Keywords></RenderingInfo></Event></Events>

Example Data as Received on the wire:

<14>1 2019-10-21T15:44:36.650065-04:00 hostname.domain Microsoft-Windows-Security-Auditing 4 - [NXLOG@14506 Keywords="-9214364837600034816" EventType="AUDIT_SUCCESS" EventID="4688" ProviderGuid="{54849625-5478-4994-A5BA-3E3B0328C30D}" Version="2" Task="13312" OpcodeValue="0" RecordNumber="355111132" ThreadID="5020" Channel="Security" Category="Process Creation" Opcode="Info" SubjectUserSid="S-1-5-18" SubjectUserName="workstation$" SubjectDomainName="DOMAIN" SubjectLogonId="0x3e7" NewProcessId="0x13a8" NewProcessName="C:\\Windows\\System32\\wbem\\WmiPrvSE.exe" TokenElevationType="%%1936" CommandLine\'/><Data_Name=\'TargetUserSid="S-1-0-0" TargetUserName="workstation$" TargetDomainName="DOMAIN" TargetLogonId="0x3e4" EventReceivedTime="2019-10-21 15:45:38" SourceModuleName="eventlog" SourceModuleType="im_msvistalog"] {"EventTime":"2019-10-21 15:44:36","Hostname":"hostname.domain","Keywords":-9214364837600034816,"EventType":"AUDIT_SUCCESS","SeverityValue":2,"Severity":"INFO","EventID":4688,"SourceName":"Microsoft-Windows-Security-Auditing","ProviderGuid":"{54849625-5478-4994-A5BA-3E3B0328C30D}","Version":2,"Task":13312,"OpcodeValue":0,"RecordNumber":355111132,"ProcessID":4,"ThreadID":5020,"Channel":"Security","Message":"A new process has been created...","Category":"Process Creation","Opcode":"Info","SubjectUserSid":"S-1-5-18","SubjectUserName":"workstation$","SubjectDomainName":"domain","SubjectLogonId":"0x3e7","NewProcessId":"0x13a8","NewProcessName":"C:\\Windows\\System32\\wbem\\WmiPrvSE.exe","TokenElevationType":"%%1936","CommandLine'/><Data Name='TargetUserSid":"S-1-0-0","TargetUserName":"workstation$","TargetDomainName":"DOMAIN","TargetLogonId":"0x3e4","EventReceivedTime":"2019-10-21 15:45:38","SourceModuleName":"eventlog","SourceModuleType":"im_msvistalog"}

NOTE: I know the above two examples don't reference the exact same event. They are just for illustration and reference purposes

You should see that in the XML exported from EventViewer, there's an empty and self-closed 'CommandLine' tag. However, in the example pulled from the wire, you should see that the 'CommandLine' tag has been mangled and parsed as if it were part of the 'TargetUserSid' tag and there's some XML data there.

Have you seen similar behavior when parsing logs either through the ForwardedEvents (Windows Event Forwarding) or otherwise?

Addendum: We have also seen this behavior with other empty, self-closed XML Fields such as a 'TargetDomainName' field, so it does not seem to be specifically related to the CommandLine tag itself.