Debugging MAPI Problems

I have been quiet here for the last month or so, one of the reasons being that I have been bogged down by a lot of application issues in production. The most recent one had to do with 4 Windows services on the production database server. Those services, developed in VB long time ago, run as work flow engines, polling/querying the database on a timer, changing the state of work flow items according to business rules and emailing the next person in the queue using MAPI function. Those services were developed at different times but they have very similar functionalities. Most of the source code was just copied from the very first one unfortunately.

About a week ago, those services started to hang - users are usually first to tell because the work flow items don't get routed after a couple of minutes as it is supposed to. I have been doing analysis with the hang dumps created by ADPLUS, arriving at the conclusion that MAPI call was the culprit. However, I haven't figured out exactly what in the MAPI call caused the problem due to lack of MAPI debug symbols. I am going to blog the debugging result anyway - hopefully someone with similar experiences with MAPI can point out the issue.

The following shows the stack of the main thread of the services that are hanging:


0:000> kb
ChildEBP RetAddr Args to Child
0012e64c 7c59a072 000005a4 00000000 00000000 NTDLL!ZwWaitForSingleObject+0xb
0012e674 7c57b3e9 000005a4 ffffffff 00000000 KERNEL32!WaitForSingleObjectEx+0x71
*** ERROR: Symbol file could not be found. Defaulted to export symbols for MSMAPI32.DLL -
0012e684 35ffbee7 000005a4 ffffffff 0de623a0 KERNEL32!WaitForSingleObject+0xf
WARNING: Stack unwind information not available. Following frames may be wrong.
0012e6fc 35f789e7 00000000 02dad738 02da27d8 MSMAPI32!FPropContainsProp+0x2612
*** ERROR: Symbol file could not be found. Defaulted to export symbols for MAPI32.DLL -
0012e744 61dd2d09 00000000 02da33f8 02da2228 MSMAPI32!MAPILogonEx+0xa7
*** ERROR: Symbol file could not be found. Defaulted to export symbols for CDO.DLL -
0012e76c 0dd025ea 00000000 02da33f8 02da2228 MAPI32!MAPILogonEx+0x79
00000000 00000000 00000000 00000000 00000000 CDO!DllUnregisterServer+0x10eea


To see what WaitForSingleObject() is waiting on:


0:000> !handle 5a4 f
Handle 000005a4
Type Mutant
Attributes 0
GrantedAccess 0x120001:
ReadControl,Synch
QueryState
HandleCount 6
PointerCount 12
Name \BaseNamedObjects\4D4150494C6F676F6E0070B872C47FD7101B8BEA00AA0038C699_S-1-5-21-1346851753-1016681682-1202159320-1002
Object specific information
Mutex is Owned


If the export symbols are close enough, the MAPILogonEx() is waiting on this mutex, which has a name suffixed with a SID, which belongs to the service account the services are running as. The SID suffix seems to reenforce the conjecture that MAPILogonEx() is being called.

While 3 out of the 4 services have their main threads like that, the forth one is different:


0:000> kb
ChildEBP RetAddr Args to Child
0012de34 7c59a072 00000664 00000000 00000000 NTDLL!ZwWaitForSingleObject+0xb
0012de5c 7c57b3e9 00000664 ffffffff 00000000 KERNEL32!WaitForSingleObjectEx+0x71
*** ERROR: Symbol file could not be found. Defaulted to export symbols for MSMAPI32.DLL -
0012de6c 35f98779 00000664 ffffffff 00000000 KERNEL32!WaitForSingleObject+0xf
WARNING: Stack unwind information not available. Following frames may be wrong.
0012de94 35f98691 00000201 0012deec 0012decc MSMAPI32!DDLUnwrapObjectEx+0xc65
*** ERROR: Symbol file could not be found. Defaulted to export symbols for EMSABP32.DLL -
0012dec4 35ae3c6e 00000004 00000201 00000000 MSMAPI32!DDLUnwrapObjectEx+0xb7d
0012df10 35ae3bbd 023e2144 00000001 023e2170 EMSABP32!ABProviderInit+0x2611
0012e028 35f72512 35f72570 360b6700 35f755d0 EMSABP32!ABProviderInit+0x2560
00000000 00000000 00000000 00000000 00000000 MSMAPI32!DDCS_Enter+0x16


This one is waiting on an event object:


0:000> !handle 664 f
Handle 00000664
Type Event
Attributes 0
GrantedAccess 0x1f0003:
Delete,ReadControl,WriteDac,WriteOwner,Synch
QueryState,ModifyState
HandleCount 2
PointerCount 4
Name
No object specific information available


I suspect this process is the owner of the mutex, although I didn't have a chance to create a kernel dump to verify.


0:000> !handle 370 f
Handle 00000370
Type Mutant
Attributes 0
GrantedAccess 0x1f0001:
Delete,ReadControl,WriteDac,WriteOwner,Synch
QueryState
HandleCount 6
PointerCount 12
Name \BaseNamedObjects\4D4150494C6F676F6E0070B872C47FD7101B8BEA00AA0038C699_S-1-5-21-1346851753-1016681682-1202159320-1002
Object specific information
Mutex is Owned


We have moved the 4 services from the database server (Win2K) to a different box (Win2K3) and there hasn't been any hang problems so far, which suggests that the MAPI problem is probably local to that machine, rather than having to do with the exchange server. Here is the detail of MAPI32.dll on the database server:


61dd0000 61df1000 MAPI32 (export symbols) MAPI32.DLL
Loaded symbol image file: MAPI32.DLL
Image path: C:\Program Files\Common Files\System\MSMAPI\1033\MAPI32.DLL
Image name: MAPI32.DLL
Timestamp: Wed Jan 13 11:08:14 1999 (369CC4EE)
CheckSum: 0002A798
ImageSize: 00021000
File version: 1.0.2536.0
Product version: 1.0.2536.0
File flags: 2 (Mask 3F) Pre-release
File OS: 40004 NT Win32
File type: 2.0 Dll
File date: 00000000.00000000
Translations: 0409.04e4
CompanyName: Microsoft Corporation
ProductName: Microsoft Exchange
InternalName: MAPI32
OriginalFilename: MAPI32.DLL
ProductVersion: 1.0
FileVersion: 1.0.2536.0
FileDescription: Extended MAPI 1.0 for Windows NT
LegalCopyright: Copyright © 1986-1999 Microsoft Corp. All rights reserved.
LegalTrademarks: Microsoft® and Windows® are registered trademarks of Microsoft Corporation.
Comments: Service Pack 3


Now back to investigating ...