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

UserEnv logging

• 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:

Process	Request	Path	Data
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
BESClient.exe	RegOpenKey	HKLM\Software\Microsoft\Windows\CurrentVersion\RunOnce	Query Value
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

Windows Auditing

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
Event ID	560	567	567
User	(my logon ID)	(my logon ID)	(my logon ID)

And here are the interesting bits of Description data for each:

Description field	First log entry	Second log entry	Third log entry
Title	Object Open:	Object Access Attempt:	Object Access Attempt:
Object Type	Key	Key	Key
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
Accesses	DELETE READ_CONTROL WRITE_DAC WRITE_OWNER Query key value Set key value Create sub-key Enumerate sub-keys Notify about changes to keys Create Link	[n/a]	[n/a]
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.

“Run Away!”

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…