im_vistalog parser failure. Introducing \n characters in syslog output that split a single record in two records... | View post

Ak0 2 years ago

Hello,

I am experiencing truncated syslog messages, and found the root cause. Event are not correctly parsed such as this example:

Here is the original message read from eventviewer:

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System> <Provider Name="Microsoft-Windows-Security-Auditing" Guid="{54849625-5478-4994-a5ba-3e3b0328c30d}" /> <EventID>4663</EventID> <Version>1</Version> <Level>0</Level> <Task>12812</Task> <Opcode>0</Opcode> <Keywords>0x8020000000000000</Keywords> <TimeCreated SystemTime="2022-09-22T13:19:53.982486800Z" /> <EventRecordID>5610</EventRecordID> <Correlation /> <Execution ProcessID="4" ThreadID="2724" /> <Channel>Security</Channel> <Computer>PC-1304.domain.priv</Computer> <Security /> </System>
<EventData> <Data Name="SubjectUserSid">S-1-5-21-894803723-839211917-112803419-1225</Data> <Data Name="SubjectUserName">username</Data> <Data Name="SubjectDomainName">Domain</Data> <Data Name="SubjectLogonId">0x71979</Data> <Data Name="ObjectServer">Security</Data> <Data Name="ObjectType">File</Data> <Data Name="ObjectName">\Device\HarddiskVolume5</Data> <Data Name="HandleId">0x1054</Data> <Data Name="AccessList">%%4416</Data> <Data Name="AccessMask">0x1</Data> <Data Name="ProcessId">0x484</Data> <Data Name="ProcessName">C:\Windows\System32\mstsc.exe</Data> <Data Name="ResourceAttributes" /> </EventData>
<RenderingInfo Culture="fr-FR"> <Message>Une tentative d’accès à un objet a été effectuée. Sujet : ID de sécurité : S-1-5-21-894803723-839211917-112803419-1225 Nom du compte : username Domaine du compte : Domain ID d’ouverture de session : 0x71979 Objet : Serveur de l’objet : Security Type d’objet : File Nom de l’objet : \Device\HarddiskVolume5\ ID du handle : 0x1054 Attributs de ressource : Informations sur le processus : ID du processus : 0x484 Nom du processus : C:\Windows\System32\mstsc.exe Informations sur la demande d’accès : Accès : Lecture données (ou liste de répertoire) Masque d’accès : 0x1</Message> <Level>Information</Level> <Task>Removable Storage</Task> <Opcode>Informations</Opcode> <Channel>Sécurité</Channel> <Provider>Microsoft Windows security auditing.</Provider>
<Keywords> <Keyword>Succès de l’audit</Keyword> </Keywords> </RenderingInfo> </Event>

Here's the corresponding syslog line produced by om_syslog. Please note that this line is spannig more than one line, this is the problem, read more please. (Forum post format may alter the rendering...)

<14>1 2022-09-22T15:19:53.982486+02:00 PC-1304.domain.priv Microsoft-Windows-Security-Auditing 4 - [NXLOG@14506 Keywords="-9214364837600034816" EventType="AUDIT_SUCCESS" EventID="4663" ProviderGuid="{54849625-5478-4994-A5BA-3E3B0328C30D}" Version="1" Task="12812" OpcodeValue="0" RecordNumber="5610" ThreadID="2724" Channel="Security" Category="Removable Storage" Opcode="Informations" SubjectUserSid="S-1-5-21-894803723-839211917-112803419-1225" SubjectUserName="username" SubjectDomainName="domain" SubjectLogonId="0x71979" ObjectServer="Security" ObjectType="File" ObjectName="\Device\HarddiskVolume5\" HandleId="0x1054" AccessList="%%4416 " AccessMask="0x1" ProcessName="C:\Windows\System32\mstsc.exe" EventReceivedTime="2022-09-22 15:20:26" SourceModuleName="eventlog" SourceModuleType="im_msvistalog"] <Event><EventTime>2022-09-22 15:19:53</EventTime><Hostname>PC-1304.domain.priv</Hostname><Keywords>-9214364837600034816</Keywords><EventType>AUDIT_SUCCESS</EventType><SeverityValue>2</SeverityValue><Severity>INFO</Severity><EventID>4663</EventID><SourceName>Microsoft-Windows-Security-Auditing</SourceName><ProviderGuid>{54849625-5478-4994-A5BA-3E3B0328C30D}</ProviderGuid><Version>1</Version><Task>12812</Task><OpcodeValue>0</OpcodeValue><RecordNumber>5610</RecordNumber><ProcessID>4</ProcessID><ThreadID>2724</ThreadID><Channel>Security</Channel><Message>Une tentative d’accès à un objet a été effectuée.

Sujet :
 ID de sécurité : S-1-5-21-894803723-839211917-112803419-1225
 Nom du compte : username
 Domaine du compte : domain
 ID d’ouverture de session : 0x71979

Objet :
 Serveur de l’objet : Security
 Type d’objet : File
 Nom de l’objet : \Device\HarddiskVolume5&#xD;
 ID du handle : 0x1054
 Attributs de ressource : 

Informations sur le processus :
 ID du processus : 0x484
 Nom du processus : C:\Windows\System32\mstsc.exe

Informations sur la demande d’accès :
 Accès : Lecture données (ou liste de répertoire)
 
 Masque d’accès : 0x1</Message><Category>Removable Storage</Category><Opcode>Informations</Opcode><SubjectUserSid>S-1-5-21-894803723-839211917-112803419-1225</SubjectUserSid><SubjectUserName>username</SubjectUserName><SubjectDomainName>Domain</SubjectDomainName><SubjectLogonId>0x71979</SubjectLogonId><ObjectServer>Security</ObjectServer><ObjectType>File</ObjectType><ObjectName>\Device\HarddiskVolume5</ObjectName><HandleId>0x1054</HandleId><AccessList>%%4416
 </AccessList><AccessMask>0x1</AccessMask><ProcessName>C:\Windows\System32\mstsc.exe</ProcessName><EventReceivedTime>2022-09-22 15:20:26</EventReceivedTime><SourceModuleName>eventlog</SourceModuleName><SourceModuleType>im_msvistalog</SourceModuleType></Event>

Problem is the AccessList value (read from the syslog message):

HandleId="0x1054" AccessList="%%4416 " AccessMask="0x1" ProcessName="C:\Windows\System32\mstsc.exe"

If we comparing XML and syslog output: XML output <Data Name="AccessList">%%4416</Data> syslog output AccessList="%%4416 " ^^^^^^^^^^^^^^^^ Mind those characters !

AccessList="%%4416 <---- a new line character is invisible but here (this is THE bug, splitting the syslog message) " <----- multiple tab characters are invisible but here (because of HTML)

End of line \x0a is record separator in syslog format so the line is split in two syslog records (of course the second record is invalid)

It seems that the content of AccessList Key Value is not extracted from XML but from the Message.

Looking at the <Message> we see AccessList is incorrect: <AccessList>%%4416
 </AccessList>

where AccessList in XML is: <Data Name="AccessList">%%4416</Data>

Conclusion there is a bug in the event parser that do not escape "#xD;
 " characters correctly, decoding the #xA; in \x0a cutting the syslog message...

You can easily reproduce the problem using this configuration:

<Input eventlog> Module im_msvistalog

SavePos	True
&lt;QueryXML&gt;
    &lt;QueryList&gt;
        &lt;Query Id=&quot;10&quot;&gt;
            &lt;Select Path=&quot;ForwardedEvents&quot;&gt;*&lt;/Select&gt;
        &lt;/Query&gt;
        &lt;Query Id=&quot;20&quot;&gt;
            &lt;Select Path=&quot;Application&quot;&gt;*&lt;/Select&gt;
            &lt;Select Path=&quot;System&quot;&gt;*&lt;/Select&gt;
        &lt;/Query&gt;
    &lt;/QueryList&gt;
&lt;/QueryXML&gt;

Exec $Message = to_xml();

</Input>

<Output debugsyslog> Module om_file File 'C:\Install\nxlog.debug.syslog.txt'

Exec to_syslog_ietf(); </Output>

<Route syslog_file> Path eventlog => debugsyslog </Route>