Be careful who you blame (another McAfee issue)

I recently talked about how third-party applications sometimes have a bad influence on other applications. In this post, I’ll continue that series.

I just got a new laptop from work preloaded with the usual stuff such as an office suite and antivirus software. I tend to prefer manually installing only the software I need when I get my hands on a new computer, but since this was for work I was pretty limited in what I was allowed to do with it. So, I just shed a tear and then went along pretending I was happy.

Not surprisingly, it didn’t take long before I started noticing problems.

Here at work, we use Exchange and Outlook 2007 for e-mail. I’ve installed two profiles, one for my Exchange account and one for my personal account. I keep the Exchange profile active most of the day (after all, I’m at work..), but occasionally I exit Outlook and switch profiles so I can check my personal e-mail.

When trying to relaunch Outlook, however, nothing happens. A quick look in Task Manager reveals two instances of the Outlook.exe process, one of them consuming more memory than the other. Killing the first process (the one with the biggest memory footprint) causes the second to continue running and the new instance of Outlook to appear.

It would seem the old instance of Outlook isn’t shutting down correctly, and the lingering process is keeping all new instances of Outlook from loading properly. This issue is quite problematic for ordinary (read: non-technical) users who think the application has already exited because the Outlook window has disappeared. Instead, they probably try to launch the application five more times before giving up and finally calling tech support.

It’s not hard to guess who gets the blame: Outlook, yet again.

The prospect of falsely blaming Outlook, and because a coworker saw similar behavior with his copy of Outlook, caused me to start digging deeper to find the root cause of why the application was hanging at shutdown. Was it really a bug in Outlook, or was it caused by something else?

The first step was to figure out when the issue surfaced. It occurred to me that I’d only noticed the behavior when I was switching from the Exchange profile to my personal e-mail profile. This lead me to believe it might be an issue with Exchange since my personal e-mail accounts only used POP3 and IMAP. The company I work for uses an off-site e-mail provider, and as such we have to log on the very first time Outlook connects to the Exchange server, Digging deeper, it turned out Outlook didn’t hang if I dismissed the Log On dialog and instead quit the application right away. Furthermore, if I did log on and the first entry in my Inbox was anything but an e-mail, such as a calendar event, and I closed Outlook before opening any e-mails, the application wouldn’t hang upon shutdown either.

Unfortunately, the previous analysis didn’t shed any light as to why this issue only happened when accessing Exchange. The natural next step was therefore to attach a debugger to the lingering process. WinDbg spat out the following message right away:

Break-in sent, waiting 30 seconds...
WARNING: Break-in timed out, suspending.
This is usually caused by another thread holding the loader lock

Aha, sounds like we’re dealing with a deadlocked process. WinDbg revealed that only two threads were left in the process:

0:000> ~* k

.  0  Id: d34.5d4 Suspend: 1 Teb: 7ffdf000 Unfrozen
ChildEBP RetAddr
0013f7bc 7c90df3c ntdll!KiFastSystemCallRet
0013f7c0 7c8025db ntdll!NtWaitForSingleObject+0xc
0013f824 7c802542 kernel32!WaitForSingleObjectEx+0xa8
0013f838 77566f71 kernel32!WaitForSingleObject+0x12
0013f854 775146e7 ole32!CDllHost::ClientCleanupFinish+0x30
0013f880 77514657 ole32!DllHostProcessUninitialize+0x80
0013f89c 774ff231 ole32!ApartmentUninitialize+0xd6
0013f8b4 774fee98 ole32!wCoUninitialize+0x41
0013f8d0 05f9d912 ole32!CoUninitialize+0x5b
WARNING: Stack unwind information not available. Following frames may be wrong.
0013fd34 05fa6b01 saPlugin+0xd912
0013fd5c 7c923aba saPlugin!DllUnregisterServer+0x62e1 ; DllMain
0013fde0 7c81ca96 ntdll!LdrShutdownProcess+0x14f
0013fed4 7c81cb0e kernel32!_ExitProcess+0x42
0013fee8 78131720 kernel32!ExitProcess+0x14
0013fef0 78131a03 msvcr80!__crtExitProcess+0x14
0013ff2c 78131a4b msvcr80!_cinit+0x101
0013ff3c 300051f6 msvcr80!exit+0xd
0013ffc0 7c817067 OUTLOOK+0x51f6
0013fff0 00000000 kernel32!BaseProcessStart+0x23

1  Id: d34.17a8 Suspend: 1 Teb: 7ffde000 Unfrozen
ChildEBP RetAddr
00fffc0c 7c90df3c ntdll!KiFastSystemCallRet
00fffc10 7c91b22b ntdll!NtWaitForSingleObject+0xc
00fffc98 7c901046 ntdll!RtlpWaitForCriticalSection+0x132
00fffca0 7c91e395 ntdll!RtlEnterCriticalSection+0x46
00fffd18 7c90e437 ntdll!_LdrpInitialize+0xf0
00000000 00000000 ntdll!KiUserApcDispatcher+0x7

The stack trace for the main thread (thread 0) shows that the application is shutting down. In fact, it’s stuck trying to uninitialize COM in the saplugin module. Let’s have a look at who owns that module:

0:000> lmvm saplugin
start    end        module name
04e20000 04e57000   saPlugin  (export symbols)  C:\Program Files\SiteAdvisor\6261\saPlugin.dll
Loaded symbol image file: C:\Program Files\SiteAdvisor\6261\saPlugin.dll
Image path: C:\Program Files\SiteAdvisor\6261\saPlugin.dll
Image name: saPlugin.dll
Timestamp:        Fri May 16 18:40:18 2008 (482DB8F2)
CheckSum:         00040AA8
ImageSize:        00037000
File version:     2.6.0.6261
Product version:  2.6.0.0
File flags:       0 (Mask 3F)
File OS:          4 Unknown Win32
File type:        1.0 App
File date:        00000000.00000000
Translations:     0409.04b0

Interesting. The module, which is called SiteAdvisor, seems to be owned by McAfee and has been installed as part of McAfee VirusScan. According to their website, SiteAdvisor protects your computer against viruses, spam, and adware. I’d previously noticed it as a plugin in Firefox, but had decided against uninstalling it in order to figure out what it actually did (who knows, maybe it did something good).

What puzzled me, however, was why it suddenly appeared in Outlook. It hadn’t been installed as an add-in, so something had to cause saplugin.dll to be loaded by Outlook. I restarted Outlook and instructed it to break whenever saplugin.dll was loaded:

0:000> sxe ld:saplugin; g

ModLoad: 06000000 06037000   C:\Program Files\SiteAdvisor\6261\saPlugin.dll
eax=00000003 ebx=00000000 ecx=0602f050 edx=f6000000 esi=00266110 edi=00000000
eip=7c90e4f4 esp=0013dc54 ebp=0013dd48 iopl=0         nv up ei pl zr na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246
ntdll!KiFastSystemCallRet:
7c90e4f4 c3

0:000> kb
ChildEBP RetAddr  Args to Child
0013dc50 7c90d50c 7c91d956 00000990 ffffffff ntdll!KiFastSystemCallRet
0013dc54 7c91d956 00000990 ffffffff 0013dd2c ntdll!ZwMapViewOfSection+0xc
0013dd48 7c91624a 001d8d10 0013ddd4 0013e2fc ntdll!LdrpMapDll+0x759
0013e008 7c9164b3 00000000 001d8d10 0013e2fc ntdll!LdrpLoadDll+0x1e9
0013e2b0 7c801bbd 001d8d10 0013e2fc 0013e2dc ntdll!LdrLoadDll+0x230
0013e318 7c80aeec 0013e338 00000000 00000000 kernel32!LoadLibraryExW+0x18e
0013e32c 10001282 0013e338 003a0043 0050005c kernel32!LoadLibraryW+0x11
WARNING: Stack unwind information not available. Following frames may be wrong.
0013e780 7e44f8ee 00050003 000c1570 0013e7ac saHook!saHooker_Uninitialize+0xc2
0013e7b4 7c90e453 0013e7c4 00000080 00000080 USER32!__fnHkINLPCBTCREATESTRUCT+0x82
0013e840 7e43e1ad 7e43e18a 00000003 000c1570 ntdll!KiUserCallbackDispatcher+0x13
0013e868 74730f0a 000102df 00000003 000c1570 USER32!NtUserCallNextHookEx+0xc
0013e8b0 7e431923 00000003 000c1570 0013e910 MSCTF!SysCBTProc+0xd2
0013e8e4 7e44f8e7 00050003 000c1570 0013e910 USER32!DispatchHookA+0x101
0013e918 7c90e453 0013e928 0000007c 0000007c USER32!__fnHkINLPCBTCREATESTRUCT+0x7b
0013e9a0 7e42e389 7e42e34f 00000000 0013eec8 ntdll!KiUserCallbackDispatcher+0x13
0013ee44 7e42e442 00000000 0013eec8 00000000 USER32!NtUserCreateWindowEx+0xc
0013eef0 7e42d0d6 00000000 32a7d830 00000000 USER32!_CreateWindowEx+0x1ed
0013ef2c 32629a19 00000000 32a7d830 00000000 USER32!CreateWindowExW+0x33
0013ef94 326d3cc1 00000000 32a7d830 00000000 mso!Ordinal6700+0x301
0013efdc 326d3ac8 0008157e 0127ad00 7c80e4cd mso!Ordinal3679+0x6b

0:000> du 0013e338 
0013e338  "C:\Program Files\SiteAdvisor\626"
0013e378  "1\saPlugin.dll"

That explained it! SiteAdvisor was injected into all processes by the means of a global hook called sahook.

Now, the stack trace shown earlier, which identified saplugin as being part of the critical path that led to the deadlock, could just as well have been caused by an earlier event that eventually manifested itself when SiteAdvisor was being unloaded. As with classic memory corruption cases, it might be the case that some other module in the process had done something bad which later caused the process to deadlock. Consequently, more digging for proof was required before blaming SiteAdvisor.

Fortunately, I didn’t have to look far. It was clear that the main thread of execution was waiting for something — after all it was stuck in a call to WaitForSingleObject. The second thread in the process was attempting to acquire a lock as can be seen by the call to RtlEnterCriticalSection:

0:000> ~1 kb
ChildEBP RetAddr  Args to Child
00fffc0c 7c90df3c 7c91b22b 00000218 00000000 ntdll!KiFastSystemCallRet
00fffc10 7c91b22b 00000218 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
00fffc98 7c901046 0197b178 7c91e395 7c97b178 ntdll!RtlpWaitForCriticalSection+0x132
00fffca0 7c91e395 7c97b178 00fffd2c 00000004 ntdll!RtlEnterCriticalSection+0x46
00fffd18 7c90e437 00fffd2c 7c900000 00000000 ntdll!_LdrpInitialize+0xf0
00000000 00000000 00000000 00000000 00000000 ntdll!KiUserApcDispatcher+0x7

0:000> !critsec 7c97b178
CritSec ntdll!LdrpLoaderLock+0 at 7c97b178
LockCount          1
RecursionCount     1
OwningThread       5d4
EntryCount         64
ContentionCount    64
*** Locked

0:000> ~
.  0  Id: d34.5d4 Suspend: 1 Teb: 7ffdf000 Unfrozen
   1  Id: d34.17a8 Suspend: 1 Teb: 7ffde000 Unfrozen

The second thread, however, is trying to acquire the loader lock, which is already owned by the main thread. The latter is in turn waiting for COM to shut down (that second thread could very well be an APC call dispatched by the COM runtime), and voilá, we have a deadlock.

MSDN states in several places that “Because there is no way to control the order in which in-process servers are loaded or unloaded, do not call CoInitialize, CoInitializeEx, or CoUninitialize from the DllMain function.” In general, doing something non-trivial in DllMain is a big no-no, and I’d expect anyone developing DLLs to have read Microsoft’s excellent document titled Best Practices for Creating DLLs.

Unfortunately, the stack trace I printed in the beginning of this post clearly shows that the saplugin module is calling CoUninitialize in its DllMain function while the loader lock has been acquired. (The loader lock is acquired by the call to LdrShutdownProcess.) This is a clear violation of the restrictions highlighted above.

I’ve uninstalled SiteAdvisor and the issue seems to be gone. Unfortunately, this case illustrates how easy it is for third-party applications to make their host applications exhibit undefined behavior.

With the previous issues I’ve had with McAfee’s software, I’m really starting to dislike the invasiveness (and buginess) of their applications.