I’ve been investigating the root cause for a critical issue
affecting my CacheMyWork app (for those of you paying attention, it has come up in the past in this column). Ever since I received my (heavily-managed) corporate laptop at work, I’ve been unable to get Windows XP to launch any of the entries that CacheMyWork populates in RunOnce.
Here’s what I knew up front
- On other Windows XP and Windows Vista systems, the same version of CacheMyWork will result in RunOnce entries that all launch at next logon
- On the failing system, the entries are still being properly populated into the Registry – after running the app, I’ve checked and the entries under RunOnce are there as expected and appear to be well-formatted
- The Event Log (System and Application) doesn’t log any records that refer even peripherally to RunOnce, let alone that there are any problems or what might be causing them
- The entries haven’t disappeared as late as just before I perform a logoff (i.e. they’re not being deleted during my pre-reboot session).
Here’s what I tried
- I added HKLM\Software\Microsoft\Windows NT\CurrentVersion\Winlogon\UserEnvDebugLevel = 30002 (hex).
- This is able to show that the processes I’m observing are firing up correctly, but there is nothing in the log that contains “runonce” or the names of the missing processes, and I haven’t spotted any entries in the log that point me to any problems with the RunOnce processing.
ProcMon boot-time logging
- I’ve got over 3.3 million records to scan through, so while I haven’t found anything really damning, I may never be 100% sure there wasn’t something useful.
- After a lot of analysis, I found a few interesting entries in the ProcMon logs:
|mcshield.exe||RegQueryValue||HKLM\SOFTWARE\Network Associates\TVD\Shared Components\On Access Scanner\BehaviourBlocking\FileBlockRuleName_2||Prevent Outlook from launching anything from the Temp folder|
|mcshield.exe||RegQueryValue||HKLM\SOFTWARE\Network Associates\TVD\Shared Components\On Access Scanner\BehaviourBlocking\FileBlockRuleName_10||Prevent access to suspicious startup items (.exe)|
|mcshield.exe||RegQueryValue||HKLM\SOFTWARE\Network Associates\TVD\Shared Components\On Access Scanner\BehaviourBlocking\FileBlockWildcard_10||**\startup\**\*.exe|
|Explorer.exe||RegEnumValue||HKLM\Software\Microsoft\Windows\CurrentVersion\RunOnce||Index: 0, Length: 220|
|waatservice.exe||RegOpenKey||HKLM\Software\Microsoft\Windows\CurrentVersion\RunOnce||Desired Access: Maximum Allowed|
I finally got the bright idea to put a SACL (audit entry) on the HKCU\…\RunOnce registry key (auditing any of the Successful “Full Control” access attempts for the Everyone special ID). After rebooting, I finally got a hit on the HKCU\…\RunOnce key:
Event Log data
First log entry
Second log entry
Third log entry
|Category||Object Access||Object Access||Object Access|
|User||(my logon ID)||(my logon ID)||(my logon ID)|
And here are the interesting bits of Description data for each:
First log entry
Second log entry
Third log entry
|Title||Object Open:||Object Access Attempt:||Object Access Attempt:|
|Object Name||\REGISTRY\USER\S-1-5-21-725345543-602162358-527237240-793951\Software\Microsoft\ Windows\CurrentVersion\RunOnce||[n/a]||[n/a]|
|Image File Name||C:\WINDOWS\explorer.exe||C:\WINDOWS\explorer.exe||C:\WINDOWS\explorer.exe|
|Access Mask||[n/a]||Query key value||Set key value|
Not that I’ve ever looked this deep into RunOnce behaviour (nor can I find any documentation to confirm), but this seems like the expected behaviour for Windows. Except for the fact that something is preventing the RunOnce commands from executing, of course.
Blocking the Mystery App?
Then I thought of something bizarre: maybe Explorer is checking for RunOnce entries to run during logon, and it isn’t finding any. Is it possible some process has deleted them during boot-up or logon, but before Explorer gets to them?
This flies in the face of my previous theory, that the entries were still there when Windows attempted to execute them, but something was blocking their execution. Now I wondered if the entries are even there to find – whether some earlier component hasn’t already deleted them (to “secure” the system).
If so, the only way to confirm my theory (and catch this component “in the act”) is if the component performs its actions on the Registry AFTER the LSA has initialized and is protecting the contents of the Registry. [It’s been too long since I read Inside Windows NT, so I don’t recall whether access to securable objects is by definition blocked until the LSA is up and ready.]
Hoping this would work, I enabled “Deny” permission for Everyone on the HKCU\…\RunOnce key for both “Set Value” and “Delete” (not knowing which one controls the deletion of Registry values in the key). This also meant that I had to enable Failure “Full Control” auditing for the Everyone group on this key as well.
However, while I’ve firmly confirmed that the Deletion takes place when I remove this Deny ACE, I can’t get Windows to log any information to indicate what process or driver is deleting the registry entries (and thus preventing Windows from executing them). It looks like – beyond what I’ve already found – there’s nothing else for which the LSA is asked to make any access control decisions for the HKCU\…\RunOnce key.
That’s all for now – I’m beat and need to regroup. If anyone has any bright ideas on ways to try to dig deeper into this system and figure out what’s missing, I’d love to hear it.
To be continued…