fibratus
fibratus copied to clipboard
rabbitstack
Not enough Kparams are reported for some kernel events
Hi,
When I read a file, I see duplicate file events (even seq numbers are different, events are the same):
Seq: 1350561
Pid: 8632
Tid: 19508
Type: ReadFile
CPU: 11
Name: ReadFile
Category: file
Description: Reads data from the file or I/O device
Host: DESKTOP-751NEI0,
Timestamp: 2021-11-13 14:41:29.7629507 +0100 CET,
Kparams: file_name➜ C:\test\yusufpapurcu.txt, file_object➜ ffffbb8962e90e90, io_size➜ 4096, irp➜ ffffbb896124ab78, offset➜ 0, type➜ file,
Metadata: ,
Pid: 8632
Ppid: 8620
Name: powershell.exe
Comm: "C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe"
Exe: C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe
Cwd: C:\Users\Yusuf-I9\
SID: DESKTOP-751NEI0\Yusuf-I9
Args: []
Session ID: 1
Seq: 1350563
Pid: 8632
Tid: 19508
Type: ReadFile
CPU: 11
Name: ReadFile
Category: file
Description: Reads data from the file or I/O device
Host: DESKTOP-751NEI0,
Timestamp: 2021-11-13 14:41:29.7631256 +0100 CET,
Kparams: file_name➜ C:\test\yusufpapurcu.txt, file_object➜ ffffbb8962e90e90, io_size➜ 4096, irp➜ ffffbb896124ab78, offset➜ 0, type➜ file,
Metadata: ,
Pid: 8632
Ppid: 8620
Name: powershell.exe
Comm: "C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe"
Exe: C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe
Cwd: C:\Users\Yusuf-I9\
SID: DESKTOP-751NEI0\Yusuf-I9
Args: []
Session ID: 1
Probably they are not duplicate and they have some more details and maybe we don't see it here? Because if you look these audit events from Event Log, it gives you more details like "ReadAttributes", "ReadEA", "READ_CONTROL" etc.
So I believe first event was reading ACL of the file, then second one was reading the content of the file. But since there is no detail about ACL etc, we see them as duplicate events. If we can see that first event was actually reading the ACL of the file, we can skip that one to make number of events less.
I hope I was able to explain well :) Sorry if I wrote it difficult.
Thanks in advance.
Hi @yusufozturk
Thanks for the elaborate analysis. Did you happen to see this pattern repeat for every file read? Does it happen only on the first read or for all subsequent read operations?
I think we could retrieve detailed file information for each freshly created file. This would allow for further creating a filter that could reject irrelevant file read operations.
Hi @rabbitstack
This is the an event from fibratus:
Seq: 58565
Pid: 7288
Tid: 8368
Type: CreateFile
CPU: 14
Name: CreateFile
Category: file
Description: Creates or opens a file or I/O device
Host: DESKTOP-751NEI0,
Timestamp: 2021-11-26 23:54:53.2839355 +0100 CET,
Kparams: file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90db488b670, irp➜ ffffb90da5461be8, operation➜ open, share_mask➜ rw-, type➜ file,
Metadata: ,
Pid: 7288
Ppid: 7228
Name: explorer.exe
Comm: C:\Windows\Explorer.EXE
Exe:
Cwd: C:\Windows\system32\
SID: DESKTOP-751NEI0\Yusuf-I9
Args: []
Session ID: 1
And this is same event from Windows Event Log:
An attempt was made to access an object.
Subject:
Security ID: DESKTOP-751NEI0\Yusuf-I9
Account Name: Yusuf-I9
Account Domain: DESKTOP-751NEI0
Logon ID: 0x2CB55
Object:
Object Server: Security
Object Type: File
Object Name: C:\test\New Text Document.txt
Handle ID: 0x2678
Resource Attributes: S:AI
Process Information:
Process ID: 0x1c78
Process Name: C:\Windows\explorer.exe
Access Request Information:
Accesses: ReadAttributes
Access Mask: 0x80
This event has type of "ReadAttributes". So I see more details in event log. I will share another one.
Thanks.
First creation of file. Fibratus:
Seq: 54987
Pid: 7288
Tid: 10684
Type: CreateFile
CPU: 10
Name: CreateFile
Category: file
Description: Creates or opens a file or I/O device
Host: DESKTOP-751NEI0,
Timestamp: 2021-11-26 23:54:52.3438011 +0100 CET,
Kparams: file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90db7495dd0, irp➜ ffffb90db608a138, operation➜ supersede, share_mask➜ rw-, type➜ file,
Metadata: ,
Pid: 7288
Ppid: 7228
Name: explorer.exe
Comm: C:\Windows\Explorer.EXE
Exe:
Cwd: C:\Windows\system32\
SID: DESKTOP-751NEI0\Yusuf-I9
Args: []
Session ID: 1
Windows Event Log:
A handle to an object was requested.
Subject:
Security ID: DESKTOP-751NEI0\Yusuf-I9
Account Name: Yusuf-I9
Account Domain: DESKTOP-751NEI0
Logon ID: 0x2CB55
Object:
Object Server: Security
Object Type: File
Object Name: C:\test\New Text Document.txt
Handle ID: 0x3770
Resource Attributes: -
Process Information:
Process ID: 0x1c78
Process Name: C:\Windows\explorer.exe
Access Request Information:
Transaction ID: {00000000-0000-0000-0000-000000000000}
Accesses: READ_CONTROL
WRITE_DAC
SYNCHRONIZE
ReadData (or ListDirectory)
WriteData (or AddFile)
AppendData (or AddSubdirectory or CreatePipeInstance)
ReadEA
WriteEA
ReadAttributes
WriteAttributes
Access Reasons: -
Access Mask: 0x16019F
Privileges Used for Access Check: -
Restricted SID Count: 0
Second file creation event from Fibratus:
Seq: 54988
Pid: 7288
Tid: 10684
Type: CreateFile
CPU: 10
Name: CreateFile
Category: file
Description: Creates or opens a file or I/O device
Host: DESKTOP-751NEI0,
Timestamp: 2021-11-26 23:54:52.3438913 +0100 CET,
Kparams: file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90db74972f0, irp➜ ffffb90db608a138, operation➜ create, share_mask➜ ---, type➜ file,
Metadata: ,
Pid: 7288
Ppid: 7228
Name: explorer.exe
Comm: C:\Windows\Explorer.EXE
Exe:
Cwd: C:\Windows\system32\
SID: DESKTOP-751NEI0\Yusuf-I9
Args: []
Session ID: 1
Windows Event Log:
An attempt was made to access an object.
Subject:
Security ID: DESKTOP-751NEI0\Yusuf-I9
Account Name: Yusuf-I9
Account Domain: DESKTOP-751NEI0
Logon ID: 0x2CB55
Object:
Object Server: Security
Object Type: File
Object Name: C:\test\New Text Document.txt
Handle ID: 0x3770
Resource Attributes: S:AI
Process Information:
Process ID: 0x1c78
Process Name: C:\Windows\explorer.exe
Access Request Information:
Accesses: WriteData (or AddFile)
Access Mask: 0x2
So I assume "supersede" means for "Read Control / Write DAC" and operation "create" is "WriteData".
726723 2021-11-27 00:55:33.8795145 +0100 CET - 2 notepad.exe (568) - EnumDirectory (class➜ Both Directory, file_name➜ New Text Document.txt, file_object➜ ffffb90db48892b0, irp➜ ffffb90d9e579138)
726724 2021-11-27 00:55:34.2867272 +0100 CET - 2 notepad.exe (568) - CreateFile (file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90db488be90, irp➜ ffffb90d9e579138, operation➜ open, share_mask➜ rw-, type➜ file)
726725 2021-11-27 00:55:34.2868219 +0100 CET - 2 notepad.exe (568) - CreateFile (file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90db488d3b0, irp➜ ffffb90d9e579138, operation➜ open, share_mask➜ r--, type➜ file)
726726 2021-11-27 00:55:34.2868691 +0100 CET - 2 notepad.exe (568) - WriteFile (file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90db488d3b0, io_size➜ 15, irp➜ ffffb90d9e579138, offset➜ 0, type➜ file)
726727 2021-11-27 00:55:34.2869214 +0100 CET - 2 notepad.exe (568) - SetFileInformation (class➜ EOF, file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90db488d3b0, irp➜ ffffb90d9e579138, type➜ file)
726728 2021-11-27 00:55:34.2869692 +0100 CET - 2 notepad.exe (568) - SetFileInformation (class➜ Allocation, file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90db488d3b0, irp➜ ffffb90d9e579138, type➜ file)
726729 2021-11-27 00:55:34.2875447 +0100 CET - 2 notepad.exe (568) - EnumDirectory (class➜ Both Directory, file_name➜ New Text Document.txt, file_object➜ ffffb90db488be90, irp➜ ffffb90d9e579138)
Is there any documentation to understand about Kparams? For example I would like to read about these: "operation➜ supersede, share_mask➜ rw-, type➜ file". Thanks.
Hi @yusufozturk
If I'm reading this correctly, all events seem to match the Windows Event Log respective. Here you can find a detailed explanation of the CreateFile event parameters. The first event you posted above is related to obtaining the read access to the file object, while the consecutive ones grants supersede and write access modes to the file object.
Hi @rabbitstack
Sorry I was working on this very late yesterday and I kinda wanted to put my finding here as a documentation for the future.
Yes, I realized that even if two events have same types, events are actually representing different activities and they are explained inside of kparams.
But there are still some events are exactly same and looks like duplicate:
**1339925** 2021-11-27 01:27:52.8575785 +0100 CET - 12 explorer.exe (7288) - CreateFile (file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90dc5449840, irp➜ ffffb90db050cbd8, operation➜ open, share_mask➜ rw-, type➜ file)
**1339926** 2021-11-27 01:27:52.8576494 +0100 CET - 12 explorer.exe (7288) - CreateFile (file_name➜ C:\test\New Text Document.txt, file_object➜ ffffb90dc5449840, irp➜ ffffb90db050cbd8, operation➜ open, share_mask➜ rw-, type➜ file)
But I did some digging over event log and I found more details about it. If I grab these events from event log, they look like following event logs:
This is first event which is same with sequence number 1339925:
[EventID: 4656] A handle to an object was requested.
Subject:
Security ID: DESKTOP-751NEI0\Yusuf-I9
Account Name: Yusuf-I9
Account Domain: DESKTOP-751NEI0
Logon ID: 0x2CB55
Object:
Object Server: Security
Object Type: File
Object Name: C:\test\New Text Document.txt
Handle ID: 0x3334
Resource Attributes: -
Process Information:
Process ID: 0x1c78
Process Name: C:\Windows\explorer.exe
Access Request Information:
Transaction ID: {00000000-0000-0000-0000-000000000000}
Accesses: DELETE
SYNCHRONIZE
ReadAttributes
Access Reasons: DELETE: Granted by D:(A;ID;0x1301bf;;;AU)
SYNCHRONIZE: Granted by D:(A;ID;0x1301bf;;;AU)
ReadAttributes: Granted by D:(A;ID;0x1301bf;;;AU)
Access Mask: 0x110080
Privileges Used for Access Check: -
Restricted SID Count: 0
And this is second event with sequence number 1339925:
[EventID: 4663] An attempt was made to access an object.
Subject:
Security ID: DESKTOP-751NEI0\Yusuf-I9
Account Name: Yusuf-I9
Account Domain: DESKTOP-751NEI0
Logon ID: 0x2CB55
Object:
Object Server: Security
Object Type: File
Object Name: C:\test\New Text Document.txt
Handle ID: 0x3334
Resource Attributes: S:AI
Process Information:
Process ID: 0x1c78
Process Name: C:\Windows\explorer.exe
Access Request Information:
Accesses: ReadAttributes
Access Mask: 0x80
So actually there are no duplicate events. But not all details are exist in the kparams, so it makes it look like duplicate.
To give some insights who will read this topic in the future, here is the difference between 4656 and 4663:
4656: https://www.ultimatewindowssecurity.com/securitylog/encyclopedia/event.aspx?eventID=4656
When you enable auditing on an object (e.g. file or folder), this is the first event recorded when an application attempts to access the object in such a way that matches the audit policy defined for that object in terms of who is requesting the access and what type of access is being requested. (it appears that two subcategories must be enabled, Handle Manipulation and one other such as File System or Registry depending on what type of object you are auditing.)
This event will be Audit Success or Audit Failure depending on whether the user account under which the account is running has the requested permissions or not.
This event's sub category will vary depending on type of object. In the example above notepad.exe running as Administrator successfully opened "New Text Document.txt" for Read access.
This event does not always mean any access successfully requested was actually exercised - just that it was successfully obtained (if the event is Audit Success of course). To determine if any of the permissions requested were actually exercised look forward in the log for 4663 with the same Handle ID.
So first event log as 4656 represents file access. If user has no access, it return an error. Second event log as 4663 represents ACL request.
4663: https://www.ultimatewindowssecurity.com/securitylog/encyclopedia/event.aspx?eventID=4663
This event documents actual operations performed against files and other objects. This event is logged between the open (4656) and close (4658) events for the object being opened and can be correlated to those events via Handle ID.
While event 4656 tells you when the object is initially opened and what type of access was requested at that time; 4656 doesn't give you positive confirmation any of the access permissions were actually exercised. That is the role of this event. This event, 4663, is logged the first time one or more of the requested permissions are actually exercised. If the program repeatedly exercises a permission while the object is open, Windows only logs 4663 the first time.
Note events 4656 and 4658 will not appear unless the subcategory "Handle Manipulation" is enabled along with the target sub-category. Microsoft explains that this was done to make it more difficult to enable these noisy events. They feel the event 4663 is better.
So summarize what we have here, first kernel event represents file access request. And if file access request is succesful (if user has enough privilege for it), then second kernel event happens and gives us information about file access type.
So maybe first kernel log should show "operation -> request" instead of "operation -> open". Otherwise both kernel events are showing same parameters and they look like duplicate. If operation is coming directly from etw, I don't know how we can make them different.
@rabbitstack I did another to test to change ACL of the file. Here are the event logs:
So we get 4663 here to learn "WRITE_DAC" means "ACL modification":
An attempt was made to access an object.
Subject:
Security ID: DESKTOP-751NEI0\Yusuf-I9
Account Name: Yusuf-I9
Account Domain: DESKTOP-751NEI0
Logon ID: 0x2CB55
Object:
Object Server: Security
Object Type: File
Object Name: C:\test\New Text Document 7.txt
Handle ID: 0x1460
Resource Attributes: S:AI
Process Information:
Process ID: 0x1c78
Process Name: C:\Windows\explorer.exe
Access Request Information:
Accesses: WRITE_DAC
Access Mask: 0x40000
And then we get 4670, to learn what exactly happened:
Permissions on an object were changed.
Subject:
Security ID: DESKTOP-751NEI0\Yusuf-I9
Account Name: Yusuf-I9
Account Domain: DESKTOP-751NEI0
Logon ID: 0x2CB55
Object:
Object Server: Security
Object Type: File
Object Name: C:\test\New Text Document 7.txt
Handle ID: 0x1460
Process:
Process ID: 0x1c78
Process Name: C:\Windows\explorer.exe
Permissions Change:
Original Security Descriptor: D:AI(A;ID;0x1301bf;;;AU)(A;ID;FA;;;SY)(A;ID;FA;;;BA)(A;ID;0x1200a9;;;BU)
New Security Descriptor: D:ARAI(A;;FA;;;S-1-5-21-463555053-3352111736-135318769-1001)(A;ID;0x1301bf;;;AU)(A;ID;FA;;;SY)(A;ID;FA;;;BA)(A;ID;0x1200a9;;;BU)
So event log shows before and after security descriptors.
And what we get through kernel events:
Pid: 7288
Ppid: 7228
Name: explorer.exe
Comm: C:\Windows\Explorer.EXE
Exe:
Cwd: C:\Windows\system32\
SID: DESKTOP-751NEI0\Yusuf-I9
Args: []
Session ID: 1
Seq: 1538826
Pid: 7288
Tid: 6304
Type: CreateFile
CPU: 1
Name: CreateFile
Category: file
Description: Creates or opens a file or I/O device
Host: DESKTOP-751NEI0,
Timestamp: 2021-11-27 14:07:14.2181442 +0100 CET,
Kparams: file_name➜ C:\test\New Text Document 7.txt, file_object➜ ffffb90dc4899d30, irp➜ ffffb90dae8da808, operation➜ open, share_mask➜ rw-, type➜ directory,
Metadata: ,
Pid: 7288
Ppid: 7228
Name: explorer.exe
Comm: C:\Windows\Explorer.EXE
Exe:
Cwd: C:\Windows\system32\
SID: DESKTOP-751NEI0\Yusuf-I9
Args: []
Session ID: 1
Seq: 1538832
Pid: 7288
Tid: 6304
Type: CreateFile
CPU: 0
Name: CreateFile
Category: file
Description: Creates or opens a file or I/O device
Host: DESKTOP-751NEI0,
Timestamp: 2021-11-27 14:07:14.2187121 +0100 CET,
Kparams: file_name➜ C:\test\New Text Document 7.txt, file_object➜ ffffb90dc4899d30, irp➜ ffffb90da3d58348, operation➜ open, share_mask➜ rw-, type➜ file,
Metadata: ,
Pid: 7288
Ppid: 7228
Name: explorer.exe
Comm: C:\Windows\Explorer.EXE
Exe:
Cwd: C:\Windows\system32\
SID: DESKTOP-751NEI0\Yusuf-I9
Args: []
Session ID: 1
So there is no information about ACL change in the parameters. Maybe it's not possible via FileIO events. I will also check other event types if they contain this information.
The reason why I'm looking into this, we use Event Logs to do File Integrity Monitoring. It's great, works very well, also it's quite fast with very low resource usage. But an attacker can always stop auditing or clear the event logs. Also auditing through event log requires user to configure it. But via kernel events, we can make this work out of box. So I'm looking how closely we can get same audit reports via kernel logs.
It's a great library btw, congrats @rabbitstack
I checked it with other kernel event types but I don't see ACL details.
This is a fabulous analysis, @yusufozturk . Thanks! For performance reasons, I think it wouldn't be viable to augment those CreateFile events from user space with detailed information about file accesses. I'll have to spend some time figuring out whether it is possible to somehow discern those events.
Our of curiosity, are you using the fibratus package directly instead of standalone binary?
Thanks @rabbitstack
If you find a way to do it or if there is a Microsoft documentation for it, I can also look into that. It's possible for me to assign someone from our team on this as well.
Yes, for performance reasons, I stripped out most of the features of the fibratus. I'm only using core part where I can read the kernel events. That would be my other feedback actually. It would be great if you would convert fibratus into the multiple repositories. If you would leave the core part out of standalone library, it would be easier to embed with other projects. I would assume that would make fibratus to reach more people.
Like same as cilium. For core part, there is a cilium/ebpf repository: https://github.com/cilium/ebpf
For network events: https://github.com/cilium/cilium
For visibility: https://github.com/cilium/hubble
So hubble and cilium uses ebpf as well and that allows us to directly embed ebpf into the projects.
Hi @yusufozturk
Thanks for offering help. I'll try to investigate over the weekend and let you know my findings.
Re. extracting ETW logic into separete repo. That makes a lot of sense, but also requires a significant amount of effort. I'll put it in the backlog as future improvements.
I've spent some time scanning through Microsoft API docs. There is a function that can obtain ACL metadata for a given file handle. Nevertheless, I think this wouldn't work for our use case because as soon as the ETW provider dispatches the event to userspace, ACL info is already altered.
I'm not sure if there are some ACL specific providers we could use to derive this insights and stich together with CreateFile events. Other then that, I don't have any smart ideas.
@rabbitstack I wasn't able to put time on this due to end of year / beginning of year work load :)
I will be active or I will assign a developer on this.
Thanks for help @rabbitstack. Great library!
@yusufozturk Have you got a chance to look into this? If there isn't anything actionable I believe we could close the issue, as this isn't really a problem with duplicate events coming out of fibratus.
@rabbitstack Oh I didn't yet but I saw your updates in the recent releases. I was planning to test it after getting the updates.
I think we can close the issue for now. I can ping you back if I have an update.
Thanks.