Winlogbeat v5 - Message not read fully

rhyse · May 26, 2016, 1:04pm

Hi

I am testing the eventlog beat for file / folder auditing. There seems to be a problem with pulling out the Access request Information of the message.

The error I am getting on the client side is

2016-05-24T20:20:17+01:00 ERR WinEventLog[Security] Dropping event. Failed to unmarshal XML='4663101281200x80200000000000006207564170SecurityFP03.domain.localS-1-5-21-4095959057-3655770624-506157572-11219suresyncDOMAIN0x2ed81b88SecurityFileH:\Data\Data\Hosting\FrankSociety\Users\Frank.Bowman_S\Scanned Documents\Welcome Scan.jpg:3or4kl4x13tuuug3Byamue2s4b0x3854%%4416
0x10x13f0C:\Program Files (x86)\Software Pursuits\SureSync 8\SPIComService451.exeAn attempt was made to access an object.

Subject:
Security ID: S-1-5-21-4095959057-3655770624-506157572-11219
Account Name: suresync
Account Domain: DOMAIN
Logon ID: 0x2ED81B88

Object:
Object Server: Security
Object Type: File
Object Name: H:\Data\Hosting\FrankSociety\Users\Frank.Bowman_S\Scanned Documents\Welcome Scan.jpg:3or4kl4x13tuuug3Byamue2s4b
Handle ID: 0x3854
Resource Attributes:

Process Information:
Process ID: 0x13f0
Process Name: C:\Program Files (x86)\Software Pursuits\SureSync 8\SPIComService451.exe

Access Request Information:
Accesses: ReadData (or ListDirectory)

Access Mask:		0x1</Message><Level>Information</Level><Task>Removable Storage</Task><Opcode>Info</Opcode><Channel>Security</Channel><Provider>Microsoft Windows security auditing.</Provider><Keywords><Keyword>Audit Success</Keyword></Keywords></RenderingInfo></Event>'. XML syntax error on line 1: illegal character code U+0005

2016-05-24T20:20:17+01:00 INFO EventLog[Security] Successfully published 99 events

Which ultimately leads to the following in Kibana: event_data.AccessList %%4416

This seems to be happening for every message of this type (I cant find one that isn't like this)

Any ideas?

Thanks

andrewkroh · May 26, 2016, 5:14pm

I think there are two separate issues here:

The XML received from Windows contains a control character resulting in an error: XML syntax error on line 1: illegal character code U+0005.
The event_data.AccessList field's value of "%%4416" is not very usable in that format. In the message's text the value appears to have been converted to "ReadData (or ListDirectory)" if I'm understanding correctly.

For the first issue, I am going to try to reproduce this locally so that I can pinpoint where the control character is. Then I'll figure what to do about it. What operating system are you using? It looks like Windows 2012.

For the second issue, I don't know %%4416 means but if anyone has some ideas on how to make that value more usable I'm happy to listen.

And for reference, I formatted the XML from the original post to make it a bit more readable:

<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="2016-05-24T19:20:15.628903500Z"/>
    <EventRecordID>6207564170</EventRecordID>
    <Correlation/>
    <Execution ProcessID="600" ThreadID="608"/>
    <Channel>Security</Channel>
    <Computer>FP03.domain.local</Computer>
    <Security/>
  </System>
  <EventData>
    <Data Name="SubjectUserSid">S-1-5-21-4095959057-3655770624-506157572-11219</Data>
    <Data Name="SubjectUserName">suresync</Data>
    <Data Name="SubjectDomainName">DOMAIN</Data>
    <Data Name="SubjectLogonId">0x2ed81b88</Data>
    <Data Name="ObjectServer">Security</Data>
    <Data Name="ObjectType">File</Data>
    <Data Name="ObjectName">H:\Data\Data\Hosting\FrankSociety\Users\Frank.Bowman_S\Scanned Documents\Welcome Scan.jpg:3or4kl4x13tuuug3Byamue2s4b</Data>
    <Data Name="HandleId">0x3854</Data>
    <Data Name="AccessList">%%4416
                </Data>
    <Data Name="AccessMask">0x1</Data>
    <Data Name="ProcessId">0x13f0</Data>
    <Data Name="ProcessName">C:\Program Files (x86)\Software Pursuits\SureSync 8\SPIComService451.exe</Data>
    <Data Name="ResourceAttributes"/>
  </EventData>
  <RenderingInfo Culture="en-GB">
    <Message>An attempt was made to access an object.

Subject:
    Security ID:        S-1-5-21-4095959057-3655770624-506157572-11219
    Account Name:       suresync
    Account Domain:     DOMAIN
    Logon ID:       0x2ED81B88

Object:
    Object Server:      Security
    Object Type:        File
    Object Name:        H:\Data\Hosting\FrankSociety\Users\Frank.Bowman_S\Scanned Documents\Welcome Scan.jpg:3or4kl4x13tuuug3Byamue2s4b
    Handle ID:      0x3854
    Resource Attributes:    

Process Information:
    Process ID:     0x13f0
    Process Name:       C:\Program Files (x86)\Software Pursuits\SureSync 8\SPIComService451.exe

Access Request Information:
    Accesses:       ReadData (or ListDirectory)
                
    Access Mask:        0x1</Message>
    <Level>Information</Level>
    <Task>Removable Storage</Task>
    <Opcode>Info</Opcode>
    <Channel>Security</Channel>
    <Provider>Microsoft Windows security auditing.</Provider>
    <Keywords>
      <Keyword>Audit Success</Keyword>
    </Keywords>
  </RenderingInfo>
</Event>

rhyse · May 26, 2016, 8:48pm

Hi

Thanks, It is Windows 2012R2.

I can send you some logs, if I can PM you ?

Ill look into the access code stuff, which at present is the main issue I have

Thanks

andrewkroh · May 26, 2016, 9:22pm

Yeah, some logs might help, particularly if the logging level is set to debug.

I turned on auditing on my test machine and haven't been able to reproduce the unmarshmaling error with any of the events that have been generated. How often is this occurring for you? Is it in every event? If you go and locate the same event in the Event Viewer using the EventRecordID, is there anything odd about the XML representation?

rhyse · May 26, 2016, 9:36pm

Hi

A bit of research around the code

Example
Accesses: READ_CONTROL
SYNCHRONIZE
ReadData (or ListDirectory)
ReadEA
ReadAttributes

Access Reasons:		READ_CONTROL:	Granted by	D:(A;;0x1200a9;;;BU)
			SYNCHRONIZE:	Granted by	D:(A;;0x1200a9;;;BU)
			ReadData (or ListDirectory):	Granted by	D:(A;;0x1200a9;;;BU)
			ReadEA:	Granted by	D:(A;;0x1200a9;;;BU)
			ReadAttributes:	Granted by	D:(A;;0x1200a9;;;BU)

Is converted to the below in XML
AccessList %%1538 %%1541 %%4416 %%4419 %%4423
AccessReason %%1538: %%1801 D:(A;;0x1200a9;;;BU) %%1541: %%1801 D:(A;;0x1200a9;;;BU) %%4416: %%1801 D:(A;;0x1200a9;;;BU) %%4419: %%1801 D:(A;;0x1200a9;;;BU) %%4423: %%1801 D:(A;;0x1200a9;;;BU)
AccessMask 0x120089

Some links below - may not be complete

http://www.slideshare.net/mpsinghrathore/windows-event-analysis - slide 18
http://www-01.ibm.com/support/docview.wss?uid=swg21435448
https://correlog.zendesk.com/entries/83901255-What-Do-NNNN-References-Mean-in-Windows-Agent-Messages-

Sample Object Access Event ID description contd Access Mask: this is the bitwise equivalent of Accesses.
Access Mask Number Access Mask Action
1537 (0x10000) Delete
1538 Read_CONTROL
1541 synchronize
4416 (0x1) ReadData(or List Directory)
4417 (0x6) WriteData(or Add File) (0x2 on Windows 2008 Server)
4418 (0x4) AppendData (or AddSubdirectory)
4419 ReadEA
4420 WriteEA
4423 ReadAttributes
4424 WriteAttributes
4432 (0x1) Query Key Value
4433 (0x2) Set Key Value
4434 (0x4) Create Sub Key

1801 seems to mean Granted

AccessMask

https://blogs.technet.microsoft.com/mspfe/2013/08/26/auditing-file-access-on-file-servers/
https://msdn.microsoft.com/en-us/library/windows/desktop/aa822867(v=vs.85).aspx

rhyse · May 26, 2016, 10:09pm

The 1st error you mention isn't happening all the time. I have enabled debugging to get some logs

andrewkroh · May 26, 2016, 10:50pm

Using Logstash I was able to setup a filter to convert those codes into a usable values stored in event_data.Accesses. It does find/replace using data from the one of the website you gave, then it splits the result into an array.

input {
  beats {
    port => 5044
  }
}

filter {
  if "AccessList" in [event_data] {
    translate {
      # Source: https://correlog.zendesk.com/entries/83901255-What-Do-NNNN-References-Mean-in-Windows-Agent-Messages-
      dictionary => [ '%%1537', "Delete",
                      '%%1538', "ReadControl",
                      '%%1539', "ReadControl",
                      '%%1540', "ReadControl",
                      '%%1541', "Synchronize",
                      '%%1542', "Synchronize",
                      '%%4416', "ReadData",
                      '%%4417', "WriteData",
                      '%%4418', "AppendData",
                      '%%4419', "ReadEA",
                      '%%4420', "WriteEA",
                      '%%4423', "ReadAttrib",
                      '%%4424', "WriteAttrib",
                      '%%1801', "Granted",
                      '%%1805', "NotGranted" ]
      field => "[event_data][AccessList]"
      destination => "[event_data][Accesses]"
      add_tag => ['accesses_translate']
      exact => false
    }

    mutate {
       split => { "[event_data][Accesses]" => " " }
    }
  }
}

output {
  stdout { codec => rubydebug { metadata => true } }
}

This is the output of the filter from Logstash. Normally you would setup Logstash to output to Elasticsearch following these directions.

{
       "@timestamp" => "2016-05-26T22:05:09.552Z",
             "beat" => {
        "hostname" => "wrks-001",
            "name" => "winlogbeat-002"
    },
    "computer_name" => "wrks-001.elastic.co",
       "event_data" => {
                "AccessList" => "%%4417\n\t\t\t\t%%4418\n\t\t\t\t",
                "AccessMask" => "0x6",
                  "HandleId" => "0x26c",
                "ObjectName" => "C:\\ProgramData\\winlogbeat\\.winlogbeat.yml.new",
              "ObjectServer" => "Security",
                "ObjectType" => "File",
                 "ProcessId" => "0x105c",
               "ProcessName" => "C:\\Program Files\\winlogbeat-5.0.0-alpha2-windows\\winlogbeat.exe",
        "ResourceAttributes" => "S:AI",
         "SubjectDomainName" => "ELASTIC",
            "SubjectLogonId" => "0x3e7",
           "SubjectUserName" => "WRKS-001$",
            "SubjectUserSid" => "S-1-5-18",
                  "Accesses" => [
            [0] "WriteData",
            [1] "AppendData"
        ]
    },
         "event_id" => 4663,
         "keywords" => [
        [0] "Audit Success"
    ],
    . . . (truncated)

andrewkroh · May 26, 2016, 11:22pm

After a bit I was able to reproduce the unmarshmaling error in my Winlogbeat log. But my error occurred on event ID 5156. I went to the Event Viewer to found the exact event by using the EventRecordId and found that not event Windows could render the event.

So now my question is how to handle these. Currently they are being dropped. Thoughts?

rhyse · May 27, 2016, 8:47am

Hi

Not sure really , the auditor in me says I need this event. The realistic side of me says it really depends on the frequency.

This is sort of related - and leads to this being an application by application basis issue
https://support.microsoft.com/en-gb/kb/2859188

Is there a way to not "read" that data and just send it through raw anyway, so that if needed we still have it in elastic search?

Thanks

andrewkroh · May 31, 2016, 10:27am

I was thinking the raw text should be indexed in Elasticsearch. We could add an error tag to the event and publish just the raw data received from Windows. We should probably filter or replace those control characters or else they could cause problems in ES or Kibana. I need to do some testing to see what works best, but this is the general direction I think we should go in for fixing this.

system · June 21, 2016, 10:27am

This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.