Définition du problème
Aléatoirement, lors de connexions RDP sur un serveur TS, le phénomène suivant se produit : après son ouverture de session, un utilisateur se retrouve uniquement avec le fond d’écran du bureau sans aucun icônes.
Action
Lors de l’apparition du problème, nous avons forcé la génération d’un memory dump du serveur manuellement:
KB254649 Overview of memory dump file options for Windows Server 2003, Windows XP, and Windows 2000 http://support.microsoft.com/default.aspx?scid=kb;EN-US;254649 KB244139 Windows feature lets you generate a memory dump file by using the keyboard http://support.microsoft.com/default.aspx?scid=kb;EN-US;244139
KB254649 Overview of memory dump file options for Windows Server 2003, Windows XP, and Windows 2000
http://support.microsoft.com/default.aspx?scid=kb;EN-US;254649
KB244139 Windows feature lets you generate a memory dump file by using the keyboard
http://support.microsoft.com/default.aspx?scid=kb;EN-US;244139
Analyse du dump
Pour le téléchargement et l’installation de Windbg, voir mon précédent post « Debugger un 100% CPU du spooler ». Concernant les commandes utilisées ici, vous pouvez trouver plus d’informations dans l’aide de Windbg.
Dans l’analyse du dump, nous pouvons voir des threads en attente d’une « critical section » (voir définition ici http://fr.wikipedia.org/wiki/Section_critique) .
Voici un exemple de thread en attente d’une « critical section » :
0:018> ~11s <- Cette commande permet de ce placer dans le contexte d’un thread en particulier, ici le thread 11 du process spoolsv.exe eax=00002f9c ebx=00000000 ecx=00000187 edx=00002f9c esi=7c8877a0 edi=00000000 eip=7c8285ec esp=01b2f3bc ebp=01b2f3f8 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: 7c8285ec c3 ret 0:011> kv <- permet d’afficher la pile du thread ChildEBP RetAddr Args to Child 01b2f3b8 7c827d0b 7c83d236 00000124 00000000 ntdll!KiFastSystemCallRet 01b2f3bc 7c83d236 00000124 00000000 00000000 ntdll!NtWaitForSingleObject+0xc 01b2f3f8 7c83d281 00000124 00000004 00000001 ntdll!RtlpWaitOnCriticalSection+0x1a3 01b2f418 7c82d243 7c8877a0 00000000 000000e9 ntdll!RtlEnterCriticalSection+0xa8 01b2f44c 7c834029 00000001 00000000 01b2f488 ntdll!LdrLockLoaderLock+0xe4 01b2f6bc 77e41bf3 027125c8 01b2f708 01b2f6e8 ntdll!LdrLoadDll+0xc9 01b2f724 77e5c70b 72451460 00000000 00000000 kernel32!LoadLibraryExW+0x1b2 01b2f738 72451310 72451460 01b2fc90 000000e9 kernel32!LoadLibraryW+0x11 01b2f750 724516f9 01b2f75c 01bf8a50 00000780 usbmon!LoadSetupApiDll+0x1f 01b2f778 72451687 72455068 01b2f794 01b2fca0 usbmon!BuildPortList+0x11 01b2f79c 76136227 00000000 00000002 00000000 usbmon!DynaMon_EnumPorts+0x64 01b2f7bc 7615c9ce 00aded40 00000000 00000002 localspl!DpEnumPorts+0x1d 01b2f808 7615d2fb 00000000 00000002 00000000 localspl!SplEnumPorts+0xb8 01b2f834 740706e4 00000000 00000002 00000000 localspl!LocalEnumPorts+0x2f 01b2f874 01008d1e 00000000 00000002 00000000 spoolss!EnumPortsW+0x6d 01b2f8a8 01006d07 00000000 00000002 00000000 spoolsv!YEnumPorts+0x8b 01b2f8cc 77c80193 00000000 00000002 00000000 spoolsv!RpcEnumPorts+0x1e 01b2f8f8 77ce33e1 01006ce9 01b2fae0 00000006 rpcrt4!Invoke+0x30 01b2fcf8 77ce35c4 00000000 00000000 000eb3b4 rpcrt4!NdrStubCall2+0x299 01b2fd14 77c7ff7a 000eb3b4 000d3888 000eb3b4 rpcrt4!NdrServerCall2+0x19
0:018> ~11s <- Cette commande permet de ce placer dans le contexte d’un thread en particulier, ici le thread 11 du process spoolsv.exe
eax=00002f9c ebx=00000000 ecx=00000187 edx=00002f9c esi=7c8877a0 edi=00000000
eip=7c8285ec esp=01b2f3bc ebp=01b2f3f8 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:
7c8285ec c3 ret
0:011> kv <- permet d’afficher la pile du thread
ChildEBP RetAddr Args to Child
01b2f3b8 7c827d0b 7c83d236 00000124 00000000 ntdll!KiFastSystemCallRet
01b2f3bc 7c83d236 00000124 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
01b2f3f8 7c83d281 00000124 00000004 00000001 ntdll!RtlpWaitOnCriticalSection+0x1a3
01b2f418 7c82d243 7c8877a0 00000000 000000e9 ntdll!RtlEnterCriticalSection+0xa8
01b2f44c 7c834029 00000001 00000000 01b2f488 ntdll!LdrLockLoaderLock+0xe4
01b2f6bc 77e41bf3 027125c8 01b2f708 01b2f6e8 ntdll!LdrLoadDll+0xc9
01b2f724 77e5c70b 72451460 00000000 00000000 kernel32!LoadLibraryExW+0x1b2
01b2f738 72451310 72451460 01b2fc90 000000e9 kernel32!LoadLibraryW+0x11
01b2f750 724516f9 01b2f75c 01bf8a50 00000780 usbmon!LoadSetupApiDll+0x1f
01b2f778 72451687 72455068 01b2f794 01b2fca0 usbmon!BuildPortList+0x11
01b2f79c 76136227 00000000 00000002 00000000 usbmon!DynaMon_EnumPorts+0x64
01b2f7bc 7615c9ce 00aded40 00000000 00000002 localspl!DpEnumPorts+0x1d
01b2f808 7615d2fb 00000000 00000002 00000000 localspl!SplEnumPorts+0xb8
01b2f834 740706e4 00000000 00000002 00000000 localspl!LocalEnumPorts+0x2f
01b2f874 01008d1e 00000000 00000002 00000000 spoolss!EnumPortsW+0x6d
01b2f8a8 01006d07 00000000 00000002 00000000 spoolsv!YEnumPorts+0x8b
01b2f8cc 77c80193 00000000 00000002 00000000 spoolsv!RpcEnumPorts+0x1e
01b2f8f8 77ce33e1 01006ce9 01b2fae0 00000006 rpcrt4!Invoke+0x30
01b2fcf8 77ce35c4 00000000 00000000 000eb3b4 rpcrt4!NdrStubCall2+0x299
01b2fd14 77c7ff7a 000eb3b4 000d3888 000eb3b4 rpcrt4!NdrServerCall2+0x19
RtlpWaitOnCriticalSection indique que ce thread est en attente sur une « critical section ».
On fait un KP pour avoir les paramètres des appels de fonctions :
0:011> kP ChildEBP RetAddr 01b2f3b8 7c827d0b ntdll!KiFastSystemCallRet(void) 01b2f3bc 7c83d236 ntdll!NtWaitForSingleObject(void)+0xc 01b2f3f8 7c83d281 ntdll!RtlpWaitOnCriticalSection( struct _RTL_CRITICAL_SECTION * CriticalSection = 0x00000124, long Increment = 4)+0x1a3 01b2f418 7c82d243 ntdll!RtlEnterCriticalSection( struct _RTL_CRITICAL_SECTION * CriticalSection = 0x7c8877a0)+0xa8 01b2f44c 7c834029 ntdll!LdrLockLoaderLock( unsigned long Flags = 1, unsigned long * Disposition = 0x00000000, void ** Cookie = 0x01b2f488)+0xe4 01b2f6bc 77e41bf3 ntdll!LdrLoadDll( unsigned short * DllPath = 0x027125c8, unsigned long * DllCharacteristics = 0x01b2f708, struct _UNICODE_STRING * DllName = 0x01b2f6e8 "setupapi", void ** DllHandle = 0x01b2f704)+0xc9 [ 01b2f724 77e5c70b kernel32!LoadLibraryExW( unsigned short * lpwLibFileName = 0x72451460, void * hFile = 0x00000000, unsigned long dwFlags = 0)+0x1b2 01b2f738 72451310 kernel32!LoadLibraryW( unsigned short * lpwLibFileName = 0x72451460)+0x11 01b2f750 724516f9 usbmon!LoadSetupApiDll( struct _SETUPAPI_INFO * pSetupInfo = 0x01b2f75c)+0x1f 01b2f778 72451687 usbmon!BuildPortList( struct DynaMon_Monitor_Info_Struct * pMonitorInfo = 0x72455068, struct Port_Update_Struct ** ppPortUpdateList = 0x01b2f794)+0x11 01b2f79c 76136227 usbmon!DynaMon_EnumPorts( unsigned short * pszName = 0x00000000, unsigned long dwLevel = 2, unsigned char * pPorts = 0x00000000 "", unsigned long cbBuf = 0, unsigned long * pcbNeeded = 0x01b2fc90, unsigned long * pcReturned = 0x01b2fca0)+0x64 01b2f7bc 7615c9ce localspl!DpEnumPorts( void * hMonitor = 0x00aded40, unsigned short * pName = 0x00000000, unsigned long Level = 2, unsigned char * pPorts = 0x00000000 "", unsigned long cbBuf = 0, unsigned long * pcbNeeded = 0x01b2fc90, unsigned long * pcReturned = 0x01b2fca0)+0x1d 01b2f808 7615d2fb localspl!SplEnumPorts( unsigned short * pName = 0x00000000, unsigned long Level = 2, unsigned char * pPorts = 0x00000000 "", unsigned long cbBuf = 0, unsigned long * pcbNeeded = 0x01b2fc90, unsigned long * pcReturned = 0x01b2fca0, struct _INISPOOLER * pIniSpooler = 0x00a956a8)+0xb8 01b2f834 740706e4 localspl!LocalEnumPorts( unsigned short * pName = 0x00000000, unsigned long Level = 2, unsigned char * pPorts = 0x00000000 "", unsigned long cbBuf = 0, unsigned long * pcbNeeded = 0x01b2fc90, unsigned long * pcReturned = 0x01b2fca0)+0x2f 01b2f874 01008d1e spoolss!EnumPortsW( unsigned short * pName = 0x00000000, unsigned long Level = 2, unsigned char * pPort = 0x00000000 "", unsigned long cbBuf = 0, unsigned long * pcbNeeded = 0x01b2fc90, unsigned long * pcReturned = 0x01b2fca0)+0x6d 01b2f8a8 01006d07 spoolsv!YEnumPorts( unsigned short * pName = 0x00000000, unsigned long Level = 2, unsigned char * pPort = 0x00000000 "", unsigned long cbBuf = 0, unsigned long * pcbNeeded = 0x01b2fc90, unsigned long * pcReturned = 0x01b2fca0, Call_Route Route = RPC_CALL (1))+0x8b 01b2f8cc 77c80193 spoolsv!RpcEnumPorts( unsigned short * pName = 0x00000000, unsigned long Level = 2, unsigned char * pPort = 0x00000000 "", unsigned long cbBuf = 0, unsigned long * pcbNeeded = 0x01b2fc90, unsigned long * pcReturned = 0x01b2fca0)+0x1e [ 01b2f8f8 77ce33e1 rpcrt4!Invoke(void)+0x30 01b2fcf8 77ce35c4 rpcrt4!NdrStubCall2( struct IRpcStubBuffer * pThis = 0x00000000, struct IRpcChannelBuffer * pChannel = 0x00000000, struct _RPC_MESSAGE * pRpcMsg = 0x000eb3b4, unsigned long * pdwStubPhase = 0x01b2fd10)+0x299 01b2fd14 77c7ff7a rpcrt4!NdrServerCall2( struct _RPC_MESSAGE * pRpcMsg = 0x000eb3b4)+0x19
0:011> kP
ChildEBP RetAddr
01b2f3b8 7c827d0b ntdll!KiFastSystemCallRet(void)
01b2f3bc 7c83d236 ntdll!NtWaitForSingleObject(void)+0xc
01b2f3f8 7c83d281 ntdll!RtlpWaitOnCriticalSection(
struct _RTL_CRITICAL_SECTION * CriticalSection = 0x00000124,
long Increment = 4)+0x1a3
01b2f418 7c82d243 ntdll!RtlEnterCriticalSection(
struct _RTL_CRITICAL_SECTION * CriticalSection = 0x7c8877a0)+0xa8
01b2f44c 7c834029 ntdll!LdrLockLoaderLock(
unsigned long Flags = 1,
unsigned long * Disposition = 0x00000000,
void ** Cookie = 0x01b2f488)+0xe4
01b2f6bc 77e41bf3 ntdll!LdrLoadDll(
unsigned short * DllPath = 0x027125c8,
unsigned long * DllCharacteristics = 0x01b2f708,
struct _UNICODE_STRING * DllName = 0x01b2f6e8 "setupapi",
void ** DllHandle = 0x01b2f704)+0xc9 [
01b2f724 77e5c70b kernel32!LoadLibraryExW(
unsigned short * lpwLibFileName = 0x72451460,
void * hFile = 0x00000000,
unsigned long dwFlags = 0)+0x1b2
01b2f738 72451310 kernel32!LoadLibraryW(
unsigned short * lpwLibFileName = 0x72451460)+0x11
01b2f750 724516f9 usbmon!LoadSetupApiDll(
struct _SETUPAPI_INFO * pSetupInfo = 0x01b2f75c)+0x1f
01b2f778 72451687 usbmon!BuildPortList(
struct DynaMon_Monitor_Info_Struct * pMonitorInfo = 0x72455068,
struct Port_Update_Struct ** ppPortUpdateList = 0x01b2f794)+0x11
01b2f79c 76136227 usbmon!DynaMon_EnumPorts(
unsigned short * pszName = 0x00000000,
unsigned long dwLevel = 2,
unsigned char * pPorts = 0x00000000 "",
unsigned long cbBuf = 0,
unsigned long * pcbNeeded = 0x01b2fc90,
unsigned long * pcReturned = 0x01b2fca0)+0x64
01b2f7bc 7615c9ce localspl!DpEnumPorts(
void * hMonitor = 0x00aded40,
unsigned short * pName = 0x00000000,
unsigned long Level = 2,
unsigned long * pcReturned = 0x01b2fca0)+0x1d
01b2f808 7615d2fb localspl!SplEnumPorts(
unsigned long * pcReturned = 0x01b2fca0,
struct _INISPOOLER * pIniSpooler = 0x00a956a8)+0xb8
01b2f834 740706e4 localspl!LocalEnumPorts(
unsigned long * pcReturned = 0x01b2fca0)+0x2f
01b2f874 01008d1e spoolss!EnumPortsW(
unsigned char * pPort = 0x00000000 "",
unsigned long * pcReturned = 0x01b2fca0)+0x6d
01b2f8a8 01006d07 spoolsv!YEnumPorts(
Call_Route Route = RPC_CALL (1))+0x8b
01b2f8cc 77c80193 spoolsv!RpcEnumPorts(
unsigned long * pcReturned = 0x01b2fca0)+0x1e [
01b2f8f8 77ce33e1 rpcrt4!Invoke(void)+0x30
01b2fcf8 77ce35c4 rpcrt4!NdrStubCall2(
struct IRpcStubBuffer * pThis = 0x00000000,
struct IRpcChannelBuffer * pChannel = 0x00000000,
struct _RPC_MESSAGE * pRpcMsg = 0x000eb3b4,
unsigned long * pdwStubPhase = 0x01b2fd10)+0x299
01b2fd14 77c7ff7a rpcrt4!NdrServerCall2(
struct _RPC_MESSAGE * pRpcMsg = 0x000eb3b4)+0x19
Ceci nous montre les paramètres des appels de fonctions et nous montre que ce thread est bloqué car il attend la « critical section » 0x7c8877a0.
0:011> dt _RTL_CRITICAL_SECTION 0x7c8877a0 spoolsv!_RTL_CRITICAL_SECTION +0x000 DebugInfo : 0x7c8877c0 _RTL_CRITICAL_SECTION_DEBUG +0x004 LockCount : -38 +0x008 RecursionCount : 1 +0x00c OwningThread : 0x000046ac +0x010 LockSemaphore : 0x00000124 +0x014 SpinCount : 0
0:011> dt _RTL_CRITICAL_SECTION 0x7c8877a0
spoolsv!_RTL_CRITICAL_SECTION
+0x000 DebugInfo : 0x7c8877c0 _RTL_CRITICAL_SECTION_DEBUG
+0x004 LockCount : -38
+0x008 RecursionCount : 1
+0x00c OwningThread : 0x000046ac
+0x010 LockSemaphore : 0x00000124
+0x014 SpinCount : 0
Cette critical section est détenue par le thread 0x000046ac.
Voyons à quel numéro de thread cela correspond :
0:011> !runaway <- permet d’afficher le temps consommé par chaque thread User Mode Time Thread Time 11:4784 0 days 0:00:01.562 13:46ac 0 days 0:00:00.890 15:4ef8 0 days 0:00:00.406 16:4f60 0 days 0:00:00.125 3:680 0 days 0:00:00.093 10:78c 0 days 0:00:00.031 22:4dc8 0 days 0:00:00.000 21:4e08 0 days 0:00:00.000 20:3bf0 0 days 0:00:00.000 19:4340 0 days 0:00:00.000 18:4b80 0 days 0:00:00.000 17:1e1c 0 days 0:00:00.000 14:4b3c 0 days 0:00:00.000 12:47f0 0 days 0:00:00.000 9:724 0 days 0:00:00.000 8:720 0 days 0:00:00.000 7:71c 0 days 0:00:00.000 6:718 0 days 0:00:00.000 5:6c4 0 days 0:00:00.000 4:68c 0 days 0:00:00.000 2:57c 0 days 0:00:00.000 1:570 0 days 0:00:00.000 0:558 0 days 0:00:00.000
0:011> !runaway <- permet d’afficher le temps consommé par chaque thread
User Mode Time
Thread Time
11:4784 0 days 0:00:01.562
13:46ac 0 days 0:00:00.890
15:4ef8 0 days 0:00:00.406
16:4f60 0 days 0:00:00.125
3:680 0 days 0:00:00.093
10:78c 0 days 0:00:00.031
22:4dc8 0 days 0:00:00.000
21:4e08 0 days 0:00:00.000
20:3bf0 0 days 0:00:00.000
19:4340 0 days 0:00:00.000
18:4b80 0 days 0:00:00.000
17:1e1c 0 days 0:00:00.000
14:4b3c 0 days 0:00:00.000
12:47f0 0 days 0:00:00.000
9:724 0 days 0:00:00.000
8:720 0 days 0:00:00.000
7:71c 0 days 0:00:00.000
6:718 0 days 0:00:00.000
5:6c4 0 days 0:00:00.000
4:68c 0 days 0:00:00.000
2:57c 0 days 0:00:00.000
1:570 0 days 0:00:00.000
0:558 0 days 0:00:00.000
On se place dans le contexte du thread :
0:011> ~13s eax=00000001 ebx=77792c30 ecx=0207f501 edx=00000000 esi=00000a60 edi=00000000 eip=7c8285ec esp=0207fd60 ebp=0207fdd0 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: 7c8285ec c3 ret
0:011> ~13s
eax=00000001 ebx=77792c30 ecx=0207f501 edx=00000000 esi=00000a60 edi=00000000
eip=7c8285ec esp=0207fd60 ebp=0207fdd0 iopl=0 nv up ei pl zr na pe nc
Puis on liste toute la stack :
0:013> kv ChildEBP RetAddr Args to Child 0207fd5c 7c827d0b 77e61d1e 00000a60 00000000 ntdll!KiFastSystemCallRet 0207fd60 77e61d1e 00000a60 00000000 00000000 ntdll!NtWaitForSingleObject+0xc 0207fdd0 77e61c8d 00000a60 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac 0207fde4 776f56f4 00000a60 ffffffff 77792cf0 kernel32!WaitForSingleObject+0x12 0207fe00 7768dac2 00000a60 00000000 00000080 ole32!CDllHost::ClientCleanupFinish+0x2a 0207fe2c 7768da32 00000000 0207fe7c 777966d4 ole32!DllHostProcessUninitialize+0x80 0207fe4c 776bce20 00000000 00000000 02702988 ole32!ApartmentUninitialize+0xf8 0207fe64 776bcdd2 0207fe7c 00000000 00000001 ole32!wCoUninitialize+0x7d 0207fe80 776e4de6 00000001 77670000 776bc793 ole32!CoUninitialize+0x65 0207fe8c 776bc793 0207feb4 776bc732 77670000 ole32!DoThreadSpecificCleanup+0x63 0207fe94 776bc732 77670000 00000003 00000000 ole32!ThreadNotification+0x37 0207feb4 776bc6da 77670000 00000003 00000000 ole32!DllMain+0x194 0207fed4 7c81a352 77670000 00000003 00000000 ole32!_DllMainCRTStartup+0x52 0207fef4 7c819178 776bc692 77670000 00000003 ntdll!LdrpCallInitRoutine+0x14 0207ffa8 77e4f920 00000000 00000000 0207ffec ntdll!LdrShutdownThread+0xd2 0207ffb8 77e6482e 00000000 00000000 00000000 kernel32!ExitThread+0x2f 0207ffec 00000000 77c7b0f5 000bb338 00000000 kernel32!BaseThreadStart+0x39
0:013> kv
0207fd5c 7c827d0b 77e61d1e 00000a60 00000000 ntdll!KiFastSystemCallRet
0207fd60 77e61d1e 00000a60 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
0207fdd0 77e61c8d 00000a60 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
0207fde4 776f56f4 00000a60 ffffffff 77792cf0 kernel32!WaitForSingleObject+0x12
0207fe00 7768dac2 00000a60 00000000 00000080 ole32!CDllHost::ClientCleanupFinish+0x2a
0207fe2c 7768da32 00000000 0207fe7c 777966d4 ole32!DllHostProcessUninitialize+0x80
0207fe4c 776bce20 00000000 00000000 02702988 ole32!ApartmentUninitialize+0xf8
0207fe64 776bcdd2 0207fe7c 00000000 00000001 ole32!wCoUninitialize+0x7d
0207fe80 776e4de6 00000001 77670000 776bc793 ole32!CoUninitialize+0x65
0207fe8c 776bc793 0207feb4 776bc732 77670000 ole32!DoThreadSpecificCleanup+0x63
0207fe94 776bc732 77670000 00000003 00000000 ole32!ThreadNotification+0x37
0207feb4 776bc6da 77670000 00000003 00000000 ole32!DllMain+0x194
0207fed4 7c81a352 77670000 00000003 00000000 ole32!_DllMainCRTStartup+0x52
0207fef4 7c819178 776bc692 77670000 00000003 ntdll!LdrpCallInitRoutine+0x14
0207ffa8 77e4f920 00000000 00000000 0207ffec ntdll!LdrShutdownThread+0xd2
0207ffb8 77e6482e 00000000 00000000 00000000 kernel32!ExitThread+0x2f
0207ffec 00000000 77c7b0f5 000bb338 00000000 kernel32!BaseThreadStart+0x39
On peu voir que ce thread est en attente avec un WaitForSingleObject.
On fait un kP pour avoir l’objet sur lequel ce thread est en attente :
0:013> kP ChildEBP RetAddr 0207fd5c 7c827d0b ntdll!KiFastSystemCallRet(void) [ 0207fd60 77e61d1e ntdll!NtWaitForSingleObject(void)+0xc 0207fdd0 77e61c8d kernel32!WaitForSingleObjectEx( void * hHandle = 0x00000a60, unsigned long dwMilliseconds = 0xffffffff, int bAlertable = 0)+0xac 0207fde4 776f56f4 kernel32!WaitForSingleObject( void * hHandle = 0x00000a60, unsigned long dwMilliseconds = 0xffffffff)+0x12 0207fe00 7768dac2 ole32!CDllHost::ClientCleanupFinish( void * hEvent = 0x00000a60)+0x2a 0207fe2c 7768da32 ole32!DllHostProcessUninitialize(void)+0x80 0207fe4c 776bce20 ole32!ApartmentUninitialize( int fHostThread = 0)+0xf8 0207fe64 776bcdd2 ole32!wCoUninitialize( class COleTls * Tls = 0x0207fe7c, int fHostThread = 0)+0x7d 0207fe80 776e4de6 ole32!CoUninitialize(void)+0x65 0207fe8c 776bc793 ole32!DoThreadSpecificCleanup(void)+0x63 0207fe94 776bc732 ole32!ThreadNotification( struct HINSTANCE__ * hDll = 0x77670000, unsigned long dwReason = 3, void * lpvReserved = 0x00000000)+0x37 0207feb4 776bc6da ole32!DllMain( void * hInstance = 0x77670000, unsigned long dwReason = 3, void * lpvReserved = 0x00000000)+0x194 0207fed4 7c81a352 ole32!_DllMainCRTStartup( void * hDllHandle = 0x77670000, unsigned long dwReason = 3, void * lpreserved = 0x00000000)+0x52 0207fef4 7c819178 ntdll!LdrpCallInitRoutine(void)+0x14 0207ffa8 77e4f920 ntdll!LdrShutdownThread(void)+0xd2 0207ffb8 77e6482e kernel32!ExitThread( unsigned long dwExitCode = 0)+0x2f 0207ffec 00000000 kernel32!BaseThreadStart( <function> * lpStartAddress = 0x77c7b0f5, void * lpParameter = 0x000bb338)+0x39
0:013> kP
0207fd5c 7c827d0b ntdll!KiFastSystemCallRet(void) [
0207fd60 77e61d1e ntdll!NtWaitForSingleObject(void)+0xc
0207fdd0 77e61c8d kernel32!WaitForSingleObjectEx(
void * hHandle = 0x00000a60,
unsigned long dwMilliseconds = 0xffffffff,
int bAlertable = 0)+0xac
0207fde4 776f56f4 kernel32!WaitForSingleObject(
unsigned long dwMilliseconds = 0xffffffff)+0x12
0207fe00 7768dac2 ole32!CDllHost::ClientCleanupFinish(
void * hEvent = 0x00000a60)+0x2a
0207fe2c 7768da32 ole32!DllHostProcessUninitialize(void)+0x80
0207fe4c 776bce20 ole32!ApartmentUninitialize(
int fHostThread = 0)+0xf8
0207fe64 776bcdd2 ole32!wCoUninitialize(
class COleTls * Tls = 0x0207fe7c,
int fHostThread = 0)+0x7d
0207fe80 776e4de6 ole32!CoUninitialize(void)+0x65
0207fe8c 776bc793 ole32!DoThreadSpecificCleanup(void)+0x63
0207fe94 776bc732 ole32!ThreadNotification(
struct HINSTANCE__ * hDll = 0x77670000,
unsigned long dwReason = 3,
void * lpvReserved = 0x00000000)+0x37
0207feb4 776bc6da ole32!DllMain(
void * hInstance = 0x77670000,
void * lpvReserved = 0x00000000)+0x194
0207fed4 7c81a352 ole32!_DllMainCRTStartup(
void * hDllHandle = 0x77670000,
void * lpreserved = 0x00000000)+0x52
0207fef4 7c819178 ntdll!LdrpCallInitRoutine(void)+0x14
0207ffa8 77e4f920 ntdll!LdrShutdownThread(void)+0xd2
0207ffb8 77e6482e kernel32!ExitThread(
unsigned long dwExitCode = 0)+0x2f
0207ffec 00000000 kernel32!BaseThreadStart(
<function> * lpStartAddress = 0x77c7b0f5,
void * lpParameter = 0x000bb338)+0x39
Puis on tape la commande suivante :
0:013> !handle 0x00000a60 Handle 00000a60 Type Event
0:013> !handle 0x00000a60
Handle 00000a60
Type Event
Cet objet est un Event, donc ce thread attend qu’un Event soit signalé.
Regardons un peu plus loin dans la stack :
0:013> kv n (le “n” permet d’afficher les numéro de frame) # ChildEBP RetAddr Args to Child 00 0207fd5c 7c827d0b 77e61d1e 00000a60 00000000 ntdll!KiFastSystemCallRet 01 0207fd60 77e61d1e 00000a60 00000000 00000000 ntdll!NtWaitForSingleObject+0xc 02 0207fdd0 77e61c8d 00000a60 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac 03 0207fde4 776f56f4 00000a60 ffffffff 77792cf0 kernel32!WaitForSingleObject+0x12 04 0207fe00 7768dac2 00000a60 00000000 00000080 ole32!CDllHost::ClientCleanupFinish+0x2a 05 0207fe2c 7768da32 00000000 0207fe7c 777966d4 ole32!DllHostProcessUninitialize+0x80 06 0207fe4c 776bce20 00000000 00000000 02702988 ole32!ApartmentUninitialize+0xf8 07 0207fe64 776bcdd2 0207fe7c 00000000 00000001 ole32!wCoUninitialize+0x7d 08 0207fe80 776e4de6 00000001 77670000 776bc793 ole32!CoUninitialize+0x65 09 0207fe8c 776bc793 0207feb4 776bc732 77670000 ole32!DoThreadSpecificCleanup+0x63 0a 0207fe94 776bc732 77670000 00000003 00000000 ole32!ThreadNotification+0x37 0b 0207feb4 776bc6da 77670000 00000003 00000000 ole32!DllMain+0x194 0c 0207fed4 7c81a352 77670000 00000003 00000000 ole32!_DllMainCRTStartup+0x52 0d 0207fef4 7c819178 776bc692 77670000 00000003 ntdll!LdrpCallInitRoutine+0x14 0e 0207ffa8 77e4f920 00000000 00000000 0207ffec ntdll!LdrShutdownThread+0xd2 0f 0207ffb8 77e6482e 00000000 00000000 00000000 kernel32!ExitThread+0x2f 10 0207ffec 00000000 77c7b0f5 000bb338 00000000 kernel32!BaseThreadStart+0x39
0:013> kv n (le “n” permet d’afficher les numéro de frame)
# ChildEBP RetAddr Args to Child
00 0207fd5c 7c827d0b 77e61d1e 00000a60 00000000 ntdll!KiFastSystemCallRet
01 0207fd60 77e61d1e 00000a60 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
02 0207fdd0 77e61c8d 00000a60 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
03 0207fde4 776f56f4 00000a60 ffffffff 77792cf0 kernel32!WaitForSingleObject+0x12
04 0207fe00 7768dac2 00000a60 00000000 00000080 ole32!CDllHost::ClientCleanupFinish+0x2a
05 0207fe2c 7768da32 00000000 0207fe7c 777966d4 ole32!DllHostProcessUninitialize+0x80
06 0207fe4c 776bce20 00000000 00000000 02702988 ole32!ApartmentUninitialize+0xf8
07 0207fe64 776bcdd2 0207fe7c 00000000 00000001 ole32!wCoUninitialize+0x7d
08 0207fe80 776e4de6 00000001 77670000 776bc793 ole32!CoUninitialize+0x65
09 0207fe8c 776bc793 0207feb4 776bc732 77670000 ole32!DoThreadSpecificCleanup+0x63
0a 0207fe94 776bc732 77670000 00000003 00000000 ole32!ThreadNotification+0x37
0b 0207feb4 776bc6da 77670000 00000003 00000000 ole32!DllMain+0x194
0c 0207fed4 7c81a352 77670000 00000003 00000000 ole32!_DllMainCRTStartup+0x52
0d 0207fef4 7c819178 776bc692 77670000 00000003 ntdll!LdrpCallInitRoutine+0x14
0e 0207ffa8 77e4f920 00000000 00000000 0207ffec ntdll!LdrShutdownThread+0xd2
0f 0207ffb8 77e6482e 00000000 00000000 00000000 kernel32!ExitThread+0x2f
10 0207ffec 00000000 77c7b0f5 000bb338 00000000 kernel32!BaseThreadStart+0x39
Nous pouvons voir que ce thread est en cours de fermeture (kernel32!ExitThread) et dans une phase de fermeture d’un thread nous notifions toutes les dlls du processus pour leurs indiquer que ce thread se termine et dans cette stack nous avons :
0b 0207feb4 776bc6da 77670000 00000003 00000000 ole32!DllMain+0x194 0c 0207fed4 7c81a352 77670000 00000003 00000000 ole32!_DllMainCRTStartup+0x52 0d 0207fef4 7c819178 776bc692 77670000 00000003 ntdll!LdrpCallInitRoutine+0x14 0e 0207ffa8 77e4f920 00000000 00000000 0207ffec ntdll!LdrShutdownThread+0xd2 0f 0207ffb8 77e6482e 00000000 00000000 00000000 kernel32!ExitThread+0x2f
On se met sur la frame 0c :
0:013> .frame 0c 0c 0207fed4 7c81a352 ole32!_DllMainCRTStartup+0x52
0:013> .frame 0c
0c 0207fed4 7c81a352 ole32!_DllMainCRTStartup+0x52
Puis on fait un DV pour afficher les paramètres :
0:013> dv hDllHandle = 0x77670000 dwReason = 3 lpreserved = 0x00000000 retcode = 3
0:013> dv
hDllHandle = 0x77670000
dwReason = 3
lpreserved = 0x00000000
retcode = 3
Regardons maintenant à quoi correspond ce « hDllHandle » :
0:013> !lmi 0x77670000 Loaded Module Info: [0x77670000] Module: ole32 Base Address: 77670000 Image Name: ole32.dll Machine Type: 332 (I386) Time Stamp: 45d70aa5 Sat Feb 17 15:01:09 2007 Size: 139000 CheckSum: 14357b Characteristics: 210e perf Debug Data Dirs: Type Size VA Pointer CODEVIEW 22, 11a44c, 11984c RSDS - GUID: {DC8A079C-AE0B-4A0C-89EC-5A936EAF1F7F} Age: 2, Pdb: ole32.pdb CLSID 4, 11a448, 119848 [Data not mapped] Image Type: MEMORY - Image read successfully from loaded memory. Symbol Type: PDB - Symbols loaded successfully from symbol server. Compiler: C++ - front end [13.10 bld 4035] - back end [13.10 bld 4035]
0:013> !lmi 0x77670000
Loaded Module Info: [0x77670000]
Module: ole32
Base Address: 77670000
Image Name: ole32.dll
Machine Type: 332 (I386)
Time Stamp: 45d70aa5 Sat Feb 17 15:01:09 2007
Size: 139000
CheckSum: 14357b
Characteristics: 210e perf
Debug Data Dirs: Type Size VA Pointer
CODEVIEW 22, 11a44c, 11984c RSDS - GUID: {DC8A079C-AE0B-4A0C-89EC-5A936EAF1F7F}
Age: 2, Pdb: ole32.pdb
CLSID 4, 11a448, 119848 [Data not mapped]
Image Type: MEMORY - Image read successfully from loaded memory.
Symbol Type: PDB - Symbols loaded successfully from symbol server.
Compiler: C++ - front end [13.10 bld 4035] - back end [13.10 bld 4035]
Nous voyons que dans la phase de shutdown on appelle OLE32 et nous somme en attente d’un Event.
En regardant les autres thread du spooler, nous pouvons voir un thread qui est dans une phase de LdrUnloadDll (déchargement d’une dll). Mais ce thread est en attente sur une « critical section » qui est celle détenue par le thread précédent :
0:013> ~18s eax=77ec1944 ebx=00000000 ecx=77e424de edx=03311b00 esi=7c8877a0 edi=00000000 eip=7c8285ec esp=032cfcb8 ebp=032cfcf4 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: 7c8285ec c3 ret 0:018> kv ChildEBP RetAddr Args to Child 032cfcb4 7c827d0b 7c83d236 00000124 00000000 ntdll!KiFastSystemCallRet 032cfcb8 7c83d236 00000124 00000000 00000000 ntdll!NtWaitForSingleObject+0xc 032cfcf4 7c83d281 00000124 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x1a3 032cfd14 7c839844 7c8877a0 032cfe70 032cfeac ntdll!RtlEnterCriticalSection+0xa8 032cfe1c 77e6b1bb 02100000 032cfeac 032cfedc ntdll!LdrUnloadDll+0x35 032cfe30 77691d0f 02100000 032cff04 77691d23 kernel32!FreeLibrary+0x41 032cfe3c 77691d23 032cfeb8 777965b0 00000000 ole32!CClassCache::CDllPathEntry::CFinishObject::Finish+0x2f 032cfe50 77691afe 77671af0 00000000 00000000 ole32!CClassCache::CFinishComposite::Finish+0x1d 032cff04 7769182a 02702bd8 00000080 776bc944 ole32!CClassCache::CleanUpDllsForApartment+0x1d0 032cff30 7769174c 00000000 032cff84 777966d4 ole32!FinishShutdown+0xd7 032cff50 776bce20 00000001 00007530 77792c30 ole32!ApartmentUninitialize+0x94 032cff68 776f5797 032cff84 00000001 77e61c96 ole32!wCoUninitialize+0x7d 032cff88 7768f2a2 032cffac 776bbab4 77792c30 ole32!CDllHost::WorkerThread+0xdd 032cff90 776bbab4 77792c30 00000000 0270a1c0 ole32!DLLHostThreadEntry+0xd 032cffac 776b1704 00000000 032cffec 77e64829 ole32!CRpcThread::WorkerLoop+0x26 032cffb8 77e64829 0270a1c0 00000000 00000000 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0x20 032cffec 00000000 776b16e4 0270a1c0 00000000 kernel32!BaseThreadStart+0x34
0:013> ~18s
eax=77ec1944 ebx=00000000 ecx=77e424de edx=03311b00 esi=7c8877a0 edi=00000000
eip=7c8285ec esp=032cfcb8 ebp=032cfcf4 iopl=0 nv up ei pl zr na pe nc
0:018> kv
032cfcb4 7c827d0b 7c83d236 00000124 00000000 ntdll!KiFastSystemCallRet
032cfcb8 7c83d236 00000124 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
032cfcf4 7c83d281 00000124 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x1a3
032cfd14 7c839844 7c8877a0 032cfe70 032cfeac ntdll!RtlEnterCriticalSection+0xa8
032cfe1c 77e6b1bb 02100000 032cfeac 032cfedc ntdll!LdrUnloadDll+0x35
032cfe30 77691d0f 02100000 032cff04 77691d23 kernel32!FreeLibrary+0x41
032cfe3c 77691d23 032cfeb8 777965b0 00000000 ole32!CClassCache::CDllPathEntry::CFinishObject::Finish+0x2f
032cfe50 77691afe 77671af0 00000000 00000000 ole32!CClassCache::CFinishComposite::Finish+0x1d
032cff04 7769182a 02702bd8 00000080 776bc944 ole32!CClassCache::CleanUpDllsForApartment+0x1d0
032cff30 7769174c 00000000 032cff84 777966d4 ole32!FinishShutdown+0xd7
032cff50 776bce20 00000001 00007530 77792c30 ole32!ApartmentUninitialize+0x94
032cff68 776f5797 032cff84 00000001 77e61c96 ole32!wCoUninitialize+0x7d
032cff88 7768f2a2 032cffac 776bbab4 77792c30 ole32!CDllHost::WorkerThread+0xdd
032cff90 776bbab4 77792c30 00000000 0270a1c0 ole32!DLLHostThreadEntry+0xd
032cffac 776b1704 00000000 032cffec 77e64829 ole32!CRpcThread::WorkerLoop+0x26
032cffb8 77e64829 0270a1c0 00000000 00000000 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0x20
032cffec 00000000 776b16e4 0270a1c0 00000000 kernel32!BaseThreadStart+0x34
Regardons quelle DLL ce thread essaie de décharger :
0:018> kP ChildEBP RetAddr 032cfcb4 7c827d0b ntdll!KiFastSystemCallRet(void) 032cfcb8 7c83d236 ntdll!NtWaitForSingleObject(void)+0xc 032cfcf4 7c83d281 ntdll!RtlpWaitOnCriticalSection( struct _RTL_CRITICAL_SECTION * CriticalSection = 0x00000124, long Increment = 4)+0x1a3 032cfd14 7c839844 ntdll!RtlEnterCriticalSection( struct _RTL_CRITICAL_SECTION * CriticalSection = 0x7c8877a0)+0xa8 032cfe1c 77e6b1bb ntdll!LdrUnloadDll( void * DllHandle = 0x02100000)+0x35 032cfe30 77691d0f kernel32!FreeLibrary( struct HINSTANCE__ * hLibModule = 0x02100000)+0x41 032cfe3c 77691d23 ole32!CClassCache::CDllPathEntry::CFinishObject::Finish(void)+0x2f 032cfe50 77691afe ole32!CClassCache::CFinishComposite::Finish(void)+0x1d 032cff04 7769182a ole32!CClassCache::CleanUpDllsForApartment(void)+0x1d0 032cff30 7769174c ole32!FinishShutdown(void)+0xd7 032cff50 776bce20 ole32!ApartmentUninitialize( int fHostThread = 1)+0x94 032cff68 776f5797 ole32!wCoUninitialize( class COleTls * Tls = 0x032cff84, int fHostThread = 1)+0x7d 032cff88 7768f2a2 ole32!CDllHost::WorkerThread(void)+0xdd 032cff90 776bbab4 ole32!DLLHostThreadEntry( void * param = 0x77792c30)+0xd [ 032cffac 776b1704 ole32!CRpcThread::WorkerLoop(void)+0x26 032cffb8 77e64829 ole32!CRpcThreadCache::RpcWorkerThreadEntry( void * param = 0x0270a1c0)+0x20 032cffec 00000000 kernel32!BaseThreadStart( <function> * lpStartAddress = 0x776b16e4, void * lpParameter = 0x0270a1c0)+0x34 0:018> !lmi 0x02100000 Loaded Module Info: [0x02100000] Module: HPBOID Base Address: 02100000 Image Name: HPBOID.DLL Machine Type: 332 (I386) Time Stamp: 45c30dad Fri Feb 02 11:08:45 2007 Size: 9000 CheckSum: e266 Characteristics: 210e Debug Data Dirs: Type Size VA Pointer CODEVIEW 54, 1458, 858 RSDS - GUID: {6D0A74B4- DFB-4467-BA2A-27942C80B5FC} Image Type: MEMORY - Image read successfully from loaded memory. Symbol Type: EXPORT - PDB not found Load Report: export symbols
0:018> kP
032cfcb4 7c827d0b ntdll!KiFastSystemCallRet(void)
032cfcb8 7c83d236 ntdll!NtWaitForSingleObject(void)+0xc
032cfcf4 7c83d281 ntdll!RtlpWaitOnCriticalSection(
032cfd14 7c839844 ntdll!RtlEnterCriticalSection(
032cfe1c 77e6b1bb ntdll!LdrUnloadDll(
void * DllHandle = 0x02100000)+0x35
032cfe30 77691d0f kernel32!FreeLibrary(
struct HINSTANCE__ * hLibModule = 0x02100000)+0x41
032cfe3c 77691d23 ole32!CClassCache::CDllPathEntry::CFinishObject::Finish(void)+0x2f
032cfe50 77691afe ole32!CClassCache::CFinishComposite::Finish(void)+0x1d
032cff04 7769182a ole32!CClassCache::CleanUpDllsForApartment(void)+0x1d0
032cff30 7769174c ole32!FinishShutdown(void)+0xd7
032cff50 776bce20 ole32!ApartmentUninitialize(
int fHostThread = 1)+0x94
032cff68 776f5797 ole32!wCoUninitialize(
class COleTls * Tls = 0x032cff84,
int fHostThread = 1)+0x7d
032cff88 7768f2a2 ole32!CDllHost::WorkerThread(void)+0xdd
032cff90 776bbab4 ole32!DLLHostThreadEntry(
void * param = 0x77792c30)+0xd [
032cffac 776b1704 ole32!CRpcThread::WorkerLoop(void)+0x26
032cffb8 77e64829 ole32!CRpcThreadCache::RpcWorkerThreadEntry(
void * param = 0x0270a1c0)+0x20
032cffec 00000000 kernel32!BaseThreadStart(
<function> * lpStartAddress = 0x776b16e4,
void * lpParameter = 0x0270a1c0)+0x34
0:018> !lmi 0x02100000
Loaded Module Info: [0x02100000]
Module: HPBOID
Base Address: 02100000
Image Name: HPBOID.DLL
Time Stamp: 45c30dad Fri Feb 02 11:08:45 2007
Size: 9000
CheckSum: e266
Characteristics: 210e
CODEVIEW 54, 1458, 858 RSDS - GUID: {6D0A74B4- DFB-4467-BA2A-27942C80B5FC}
Symbol Type: EXPORT - PDB not found
Load Report: export symbols
Conclusion
Ici le problème semble lié au module HPBOID.
Résolution
Nous avons dans un premier temps renommé ce composant afin de vérifier :
1. Si cela permettait de résoudre le problème (ce fût le cas)
2. De s’assurer que cela n’avait pas d’impact sur le bon fonctionnement des imprimantes.
Ensuite, il a fallut contacter l’éditeur de ce composant afin soit de le désinstaller sans impacter les imprimantes ou de se procurer une version mise à jour corrigeant ce problème.
Bon réveillon et bonne année.
Philippe
Windows Core Support Escalation Engineer