An Explosion of Audit Records
One of the topics I cover in the security module of the Windows internals seminar that I teach with Dave Solomon is auditing. I demonstrate object access auditing by enabling failure auditing in the Local Security Policy Editor (which you launch by typing secpol.msc in the Run dialog), removing all access to a folder on the system, adding failure auditing to the folder’s System Access Control List (SACL) in Explorer’s permissions editor dialog, and finally, generating failure audits by attempting to navigate into the directory.
In order to verify that audit records generate I open the Security event log in the Event Viewer. Explorer presents an access denied message box exactly once when I try to open the locked-down directory, so when I performed the demonstration for the first time I expected to see one failure audit record. To my amazement and confusion, however, I saw something like this:
I cleared the security event log immediately before causing the error so the 109 events the Event Viewer reports are in the log are all related to one access denied operation in Explorer. Its no wonder auditing is turned off by default! When one user action generates 109 events it’s pretty easy to craft an attack that effectively deletes the useful contents of the security event log.
Every time I’ve performed the demonstration I’ve glossed over the fact that there are far more events than I expect to see and make a mental note that I should investigate what’s going on. When I finally got around to it my first step was to run Filemon and see what’s happening behind the scenes. Filemon confirmed that Explorer is indeed trying to open the file 109 times:
My next question was of course, why? To get the answer to this I first decided to see how Explorer behaves when I navigate into a directory successfully. I created another directory and opened it with Filemon watching:
After trying the experiment a few times I realized that the file access attempts occur when I click on the folder, not when I try and navigate into it. It looks like Explorer checks for the presence of several variants of “summary information” alternate data streams on the directory. Not only that, but it looks like it checks for the same ones over and over. These summary information streams are the same ones that Explorer creates when you enter information on the summary tab of a file’s properties dialog box:
If you watch Explorer query a file when you open a file’s properties with Filemon you’ll see the same alternate data stream queries we saw it execute on the locked-down folder:
Several questions remained open to me at this point. First, why is Explorer even looking for properties on a folder when a user simply selects the folder? Second, Explorer doesn’t present the Summary tab in the properties dialog box for folders, so why does it expect to find properties on a folder? Finally, why does it try to read the same streams repeatedly, even in the face of errors?
A hypothesis that addresses the first two questions is that the distinction between files and folders with respect to displaying summary information tabs on properties dialog is at a higher layer than the code that checks for the presence of the summary information streams. Besides allowing you to configure columns that show summary information in its Details view, Explorer shows the information in the tooltip it pops open if you hover the mouse over a selected item long enough. It must be attempting to gather that information ahead of time.
I figured a look at Explorer’s stack during one of the stream queries might shed some light on the other third question. I couldn’t simply set a breakpoint on CreateFile, the API used to open files, because that’s one of the most commonly used APIs on a system. Instead, I set the breakpoint on SepOpenAuditAlarm, the kernel-mode Security Reference Monitor function that NTFS calls when it wants to write an event to the security event log. Here’s part of the stack trace that I got:
The highlighted frame is the one that shows the name of the function, CPropStgColumns::GetItemData, that kicks off the repeated queries. Its name confirms that it has something to do with the Details view columns and likely the tooltip, but the trace doesn't explain why its querying the same streams repeatedly or why it keeps trying when the access denied errors should cause it to give up.
Anybody from the Shell team out there?
Originally by Mark Russinovich on 6/15/2005 5:39:00 PM
Migrated from original Sysinternals.com/Blog
# re: An Explosion of Audit Records
I guess that helps explain why navigating through folders across a WAN link is so @#!*$-ing slow! Don't suppose anyone knows a way to disable all that property reading when accessing network shares and have windows explorer simply give me my list of file and folder names like a good doggy?
6/16/2005 7:09:00 AM by Anonymous
# re: An Explosion of Audit Records
Not that this helps, but i know some of bloat due to things like desktop.ini that they use to give different experinces to folders (like downloaded program files). To render a folder that way it has to be "system".
It will even do this across a network connection. So you can setup a netmon traces and open a network folder and watch all the things it tries to open....it has gotten better, but still way to many things going on under the covers.
6/16/2005 7:40:00 AM by Josh
# re: An Explosion of Audit Records
Wow - that explains a lot. No wonder why I like Servant Salamader so much better as an explorer replacement. I did a filemon on that and it didn't have any of those queries.
Thanks for digging into that!
6/16/2005 7:50:00 AM by Damon
# re: An Explosion of Audit Records
I have alwaus unchecked "Show pop-up description for folder and desktop items" in folder options. It seems like brosing through network folder gets faster this way. Maybe this will help?
6/16/2005 2:40:00 PM by Priit
# re: An Explosion of Audit Records
Also, List view has a lighter foot print on browsing than thumb or details view
6/16/2005 7:04:00 PM by Anonymous
# re: An Explosion of Audit Records
This might also tie into the Scripting.FileSystemObject COM object. When iterating files and folders using this object - especially over a WAN - it is significantly slower than using FindFirstFile/FindNextFile. I have forever been annoyed with slow Explorer performance over the WAN. This really helps explain a lot. I can get better WAN performance by disabling automatic antivirus checking. Explorer must open each file scanning for the file's ICON, forcing antivirus software to scan the file. I hope MS can do something about it.
6/17/2005 9:57:00 AM by Anonymous
# re: An Explosion of Audit Records
Hmmm... When Windows can't access or delete something, it doesn't just give up and error out right away. It waits a short while and continues to retry until finally giving up. Sometimes this helps avoid unnecessary access errors.
6/19/2005 4:59:00 PM by Anonymous
# re: An Explosion of Audit Records
I've received e-mail from the program manager responsible for Windows auditing at Microsoft. He says Microsoft has acknowledged the Explorer I show as a bug and will fix it, and other similar Explorer behaviors, in Longhorn.
6/24/2005 11:35:00 AM by Mark Russinovich
# re: An Explosion of Audit Records
Good, but Longhorn is 2 years away. Can they do a hotfix for XP? Or may be XP SP3?
6/27/2005 8:40:00 AM by Anonymous
# re: An Explosion of Audit Records
speaking of multiple access attempts that defy explanation... I have my Windows servers set to auto-lock an account after 10 failed logon attempts, plus I have logon event auditing enabled. I've noticed that when I create an account on a server with the same username as what I have on my workstation, but assign a different password, then try to connect to a share on that server, Windows sends my workstation's username/password & fails 10 times, the new account on the server locks, then Windows tries 2 more times to send the username/password, then notices that the account is locked out (and displays a "referenced account is locked out" dialog box on my workstation). I never get prompted to enter an alternate username or password. My workstation is XP Pro SP2 and the server in question is 2000 SP4 Server.
When I do the same thing while logged on as a user that doesn't exist on the server, it tries & fails to authenticate 13 times with my system's current credentials, then it decides to finally prompt me for a different username/password. I did this test from a 2003 SP1 "client" on the same 2000 SP4 server.
Could this be related? I really can't think of any reason why Windows would try to authenticate more than once.
6/27/2005 5:25:00 PM by shaun
# re: An Explosion of Audit Records
Thank you for looking into this, it;s very informative.
We have a couple of folders on a W2K3 server that are always slow to open. Using Filemon I can confirm the same behaviour with multiple retries going on in the background, and in one of the cases the $data is replaced with seemingly ramdon characters.
Fingers crossed your friends in high places can issue a hotfix.
6/27/2005 7:35:00 PM by Anonymous
# re: An Explosion of Audit Records
This kind of thing should have been fixed in win95.
Has anyone seen the same mess with alternate shells...over a WAN link as well?
6/27/2005 7:59:00 PM by Anonymous
# re: An Explosion of Audit Records
The Explorer in Windows Vista Beta 1 is indeed quite a bit faster than the Explorer in Windows XP on the same hardware. So I guess Microsoft fixed a lot of those issues.
7/28/2005 2:43:00 PM by Erwyn van der Meer
# re: An Explosion of Audit Records
No, the problem is not so easy. When data is transmitted over the network data packets get lost very often, and those lost packets have to be resend otherwise the data is useless. The problem makes programmers to set loops so it attempts many times to perform the same task instead displaying message "Sorry! Please try again." Believe me it will annoy you much more. Personally in my systems I set loop for 25 comparing to Microsoft which is twice lower in its standards. :)
8/3/2005 2:14:00 PM by aliai
# re: An Explosion of Audit Records
If you don't have a kernel debugger installed it would be just as fast to use an undocumented feature of SetLastError. As CreateFile uses the last error mechanism, it's possible to detect when the last error value is set in user mode. SetLastError checks a global variable when it's called and if the value being set matches the variable, it breaks into the debugger.
I’ve written a little more on it at https://sandbox.zeroaffinity.com/2005/08/02/7.
8/6/2005 4:33:00 PM by Dan
# re: An Explosion of Audit Records
>When data is transmitted over the network data packets get lost very often.
UDP packets, true; but TCP connections are supposed to automatically retry the packet and eventually fail when the retry count is reached.
I wonder if this is related to the huge file copied across LAN bogging down problem? M$ has said it is a priority inversion in explorer and LanMan. To me it seems to behave as if the remote machine is doing a flush, rewind and seek deeper into the file taking longer each time a block is transfered. I also wonder if it isn't related to file change notification messages.
8/22/2005 7:56:00 PM by Anonymous
# re: An Explosion of Audit Records
I've been scratching my head over this issue for ages and this page was about the only one with any info on it at all. A customer's access to a network share had slowed down from instantaneous to taking up to 60 secs to display the contents of a folder.
As it turns out the solution is amazingly simple. Somehow this folder had been marked by windows as containing pictures and then also the folder had been set to 'arrange icons by -> picture taken on'. This causes explorer to dive into the ADS' to try to locate the info. If you set 'Arrange icons by -> name' or reset the folder view the problem goes away!
10/15/2005 7:44:00 AM by Rick K
# re: An Explosion of Audit Records
Leading on from this, I have an interesting problem regarding summary information. My XP Pro will save summary info for all supported file types (txt pdf etc) but not picture types (jpg tiff). It used to, and I still have files with Title info but if I try to change it or enter something for a new picture file...nothing. I cannot find any reference to this problem on the Web, am I alone? I am still not sure if the info is written to the file or the directory, is it EXIF or metadata?Microsoft's KB is the usual waste of time. Mark's research is the only thing I have found that is close to being helpful. When I run Filemon I have Msctf.dll & Msimtf.dll coming up, explorer creates a SIV?.TMP file then there is QUERY INFO - INVALID PARAMETER FileAttribute TagInformation. Any body else been here?
1/22/2006 7:30:00 AM by Clive
# re: An Explosion of Audit Records
I've implemented some of the recommendations for speeding up "folder" access like using a mapped drive instead of a desktop shortcut to the shared folder but I'm stilled dogged with very slow "file" access in the share. While opening and browsing the shared folder is much faster now, it still can take up to a minute to open and save/close a file in this share. Windows XP Pro clients, Server 2003 SP1 server. FYI, this is one of the web articles I came across while googling for answers to this problem. This article seems related but I'm not sure.
~andy otro.pinguino[a t] gmail[do t]com
4/7/2006 6:59:00 AM by Anonymous
# re: An Explosion of Audit Records
These are some reghacks to help with the "slowness" in file browsing:
https://support.microsoft.com/kb/885189/
https://support.microsoft.com/kb/816375/
https://support.microsoft.com/kb/319470/
https://support.microsoft.com/kb/265396/
4/21/2006 8:49:00 AM by Anonymous
# re: An Explosion of Audit Records
[a long time since the last blog-entry, I know ;-) ]
while searching for useful sourcecode to delete alternate datastreams [ADS], I found this blog ;-)
The enhanced security since XP-SP2 [also on Server 2003 R2] - so far it looks to me - forces explorer the check [possibly each?] file for ADS. If one donwloads a file from the internet and stores it into the local filesystem, an ADS is created and later is checked, if the source can be verified as "secure" !!! I am currently on the road to migrate to x64 and so I had to download a reasonable amount of tools and drivers. One day - I was using LADS [www.heysoft.de] to enumerate streams - I found the following:
\products\DaemonTools--DaemonTools-4.01-x64\daemon401-64.exe:Zone.Identifier
Any my download-path was filled with this streams!!!!!
If one double-clicks the exe in windows explorer, one get's a security warning, because the file cannot be identified to come from a secure source!!!!!! You must explicitely click "yes", to run this executable! What a mess! Or not? I usually [mostly ;-) ], know, what I click on ..... but for other users, this may be a really useful protection.
So far is see, this forces explorer to check every file to have that ADS!
One can disable this feature in the registry or via policies. If one opens the property dialog, one can remoce this ADS.
Regards,
Manfred
5/11/2006 5:30:00 PM by Anonymous