Month: March 2008

Operational Event 567? Maybe sometimes.

ingmar.koecher 0 Comment Event Log, EventSentry, Tips & Tricks

In my previous post I explained when and why 560 events are logged, and roughly explained why they are only of limited usefulness since they only log what a user could have done, not what they actually did.

Starting with Windows XP and Windows Server 2003, Microsoft introduced the so-called operational event 567. This event is supposed to enhance the auditing experience by not only logging what a user could do, but instead what he actually did! Does this sound too good to be true? Well, I guess that’s because it almost is.

According to Eric Fitzgerald’s Object Access Auditing Overview (Eric is the former head of the Windows Auditing Team), the 567 event should be logged in between the 560 (open handle) and 562 (close handle) events.

As such, the idea behind the 567 is simple:

1. User opens text file backup.cmd with a text editor. Event 560 is logged which includes all the rights the user will have to the document backup.cmd.

2. The user hits the save button, and Windows logs event 567, most likely including the WRITE_DATA access mask which indicates that data was written to the file. Note that the 567 event will not, unlike the 560 event, include the file name in the message text, but instead just the value of the handle that was included in the previously logged 560 event. As such, to make use of that event, you will have to go back to the 560 event to figure out which file was affected by the subsequently logged 567 event.

3. When the user closes the file, event 562 is logged. This event also only includes the value of the handle which was returned by the previously logged 560 event.

Well, you can imagine that I got pretty excited after doing all the research and was ready to see that 567 event in action on our production and test network. So I enabled auditing on a folder and started creating files, modifying files and so forth. Events 560 and 562 were logged just fine and as expected, but I had difficulties seeing a 567 event – it just wasn’t there. Since there is no option to turn event 567 on or off, I wasn’t exactly sure what I was doing wrong. I was ready to give up – after all I was quite tired that night, but after playing around more, trying different operating systems, different auditing options, logging on locally etc. I finally saw the 567 event. Hooray!

All seemed well until the next morning, when I tried to continue last night’s work and got stuck again. No 567 event. I then remember Eric’s blog entry, where he pointed out that event 567, due to a bug, wasn’t logged when files were accessed through a file share unless you had WinXP SP2 or Win2k3 SP1. Surely this couldn’t be a problem in my network, since I was running SP2 on XP and Windows Server 2003. Well, it was the best hint I had to work with, and so I compared local and remote file access auditing to see if it would make a difference.

Bingo!

As it turned out, event 567 was only logged when I accessed files locally, that is if the file that was audited resided on the same machine that I had logged on to. As soon as I accessed a file through a file share (as most people do), event 567 was not logged.

I was still confused though, after all I had read about the 567 event not only in Microsoft’s documentation and blog, but also at other trustworthy sources and still thought that maybe something was off in my environment. Maybe I was missing a hotfix or some other secret ingredient that would prevent my server from generating the highly desired 567 event.

So expanded my tests to another test network, another production network, a SBS 2003 network and so on and so on. The results were always the same, event 567 was not logged when I accessed the audited file through a file share.

Since I ran out of options and the existence vs. non-existence of the 567 affected development of a new EventSentry feature, I opened up a support call with Microsoft’s Enterprise Support. After an hour of mostly hold time and an actually helpful engineer, it turns out that event 567 is indeed only logged sometimes. The engineer didn’t want to be too specific, but the bottom line was that one should not except the 567 event to always be logged when a 560/562 event pair was logged. Asking why that was the case, I was told that implementing event 567 “correctly” would have required a kernel change which was not an option. So there you have it.

I stick to my “research” however – event 567 is indeed logged as long as you are accessing the audited files locally, and not through a network share. Otherwise you will have make do with the 560/562 events.

Of course you can also upgrade to Vista or Windows Server 2008, which log event 4663 (= 567 + 4096) regardless of whether you access the file locally or remotely. This event also includes the full filename and path, so collecting the related 4656 and 4658 events is not necessary. I have verified it with both, and it works very well indeed.

Thankfully, EventSentry 2.90 (when released) will take most of that burden of you and perform some additional  work for you to give a crisp idea of who is modifying/creating/deleting which file at what time.

Enjoy!

Tracking Objects with 560 and 562 Object Access events

ingmar.koecher 0 Comment Event Log, Tips & Tricks

One of the upcoming features in the 2.90 release of EventSentry is file object tracking, which will – as the name implies – track file access!

EventSentry already tracks process activity by intercepting and analyzing the 592 and 593 security events that are generated when a process starts or exits respectively; we also track logons and logoffs by intercepting and analyzing the various logon (e.g. 528) and logoff events. Tracking object access turns out to be a bit more involved as process and logon tracking, since Windows 2003 and earlier don’t actually log when an object is modified, but instead log when an object handle is being returned to the caller. I would like to mention here that object auditing has been drastically improved in Vista and later, but more on that next week.

But before I explain the 560, 562 and the problematic 567 events, let’s make sure we have everything setup for auditing to work.

1. Make sure that “Audit Object Access” is active on the machine where the files will be accessed. In most cases this will be your file server, and you will probably want to configure this with a group policy object and apply this setting to all machines from which you plan on collecting object audit events.

2. Once auditing is enabled on the machine, you will have to tell Windows which files you effectively want to audit, since generating an audit event for every single file by default would fill up your security event log quicker than you could get a cup of coffee. To audit a folder, bring up the security properties of the folder, click advanced and select the “Auditing” tab. Here you will specify which accesses and users will be audited, and I recommend that you always use Everyone when adding an audit entry to ensure that all object access is audited. I also recommend only auditing the access type you really care about. since 560 events can quickly fill up your event log (and consequently any consolidated database you might have) and there is no reason to monitor accesses you’re not concerned with (e.g. ReadAttributes).

Now to get back to the 560 and 562 events, this is better explained with an example. In Windows, when you need to read or write to a file, you usually call the CreateFile() API function which will return a handle to the object (=file in this case) you are about to access. When calling CreateFile(), you tell Windows which access to the file you need. For example, when you simply need to read from a file then you can pass GENERIC_READ (or the more specific FILE_READ_DATA) for the dwDesiredAccess parameter.

Assuming that you are allowed READ access to the file, Windows will return a handle to the requested file (that you can now use in subsequent ReadFile() operations). And this is exactly where Windows logs the 560 Audit Success event (assuming of course the access type and user match the auditing enries), essentially documenting that an object handle was returned. While this all sounds nice and dandy, the problem with the 560 event is that it doesn’t actually tell you what the caller ended up doing with that handle. Even if the caller where to close the handle right away with CloseHandle(), the 560 event would have still been logged – even if the caller never actually accessed the file.

The same holds true for potential write access to a file. If I access a file with the GENERIC_WRITE access right, then Windows will log a 560 event that looks similar to this:

Object Open:
Object Server: Security
Object Type: File
Object Name: E:\Folder\Customers\Sheet.xls
Handle ID: 20084
Operation ID: {0,93244500}
Process ID: 4
Image File Name:
Primary User Name: DC1$
Primary Domain: ESDOMAIN
Primary Logon ID: (0x0,0x3E7)
Client User Name: support.engineer
Client Domain: ESDOMAIN
Client Logon ID: (0x0,0x58C5419)
Accesses: READ_CONTROL
ReadData (or ListDirectory)
WriteData (or AddFile)
AppendData (or AddSubdirectory or CreatePipeInstance)
ReadEA
WriteEA
ReadAttributes
WriteAttributes

At first glance, one would assume that support.engineer wrote to the file, after all WriteData is included in the listed Accesses. This is far from accurate however, since the user could have closed the file right-away again (without ever reading or writing data from/to it) and the event would have still been logged in exactly the same manner.

This means that unless you manually verify some properties of the file, for example the access stamps, size or checksum, the 560 events only tell you what a user could have done, not what they actually did.

When the calling process is done working with the file, it will call CloseHandle() to close the handle it had previously opened. As such, a 560 event is always followed by a 562 event that includes the same handle ID as the original 560 event.

At some point during the Windows XP development, Microsoft seems to have realized that the 560 events are limited in their usefulness (at least for authorized access), and introduced the 567 event, also called an “operational event”. The purpose of the 567 event is not to log when a handle is returned, but instead when a file is actually being accessed – much more useful – at least in theory. So even though the 567 event was created to solve the problems of the 560 event, it does so only under limited circumstances.

But since I already wrote more on this subject than most people probably want to read, I will explain the 567 event in all detail in my next post this weekend.