Зависание на Shutdown-е (AVer Quick)

   Иногда при завершении работы системы система мне показывает диалог "Ожидание" со временем переходящее в "Зависание" ([1], Windows XP) с жалобой "Приложение AVer Quick не отвечает".
   AVer Quick (AVerQuick.exe) - это часть ПО от TV-тюнера AverMedia.


   И вот в однажды, когда система в очередной раз пожаловалась, с помощью Process Explorer-a, для разбора полетов был снят полный дамп с этого процесса ([2]).

   В полученном дампе оказалось всего два потока:

0:000> ~
.  0  Id: 790.794 Suspend: 0 Teb: 7ffdf000 Unfrozen
   1  Id: 790.230 Suspend: 0 Teb: 7ffde000 Unfrozen

   Посмотрим на полный стек главного потока:

0:000> kv
ChildEBP RetAddr  Args to Child              
0012c8d0 7c90df5a 7c91b24b 00000138 00000000 ntdll!KiFastSystemCallRet
0012c8d4 7c91b24b 00000138 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
0012c95c 7c901046 00885780 7c810245 7c885780 ntdll!RtlpWaitForCriticalSection+0x132
0012c964 7c810245 7c885780 00000001 00000001 ntdll!RtlEnterCriticalSection+0x46 ;  6 
0012cb98 1001a165 0044cff1 10015696 00000000 kernel32!SetUnhandledExceptionFilter+0x4d ;  5 
WARNING: Stack unwind information not available. Following frames may be wrong.
0012cbf0 7c90118a 10000000 00000001 00000000 GraphMaster!DllUnregisterServer+0xcfa3
0012cc10 7c91e044 100148c0 10000000 00000000 ntdll!LdrpCallInitRoutine+0x14 ;  4 
0012cd08 7c80ac97 10000000 0012cd44 0012ce70 ntdll!LdrUnloadDll+0x41c
0012cd1c 7751fc3a 10000000 0012ce8c 7751fc4e kernel32!FreeLibrary+0x3f ;  3 
0012cd28 7751fc4e 0012cd50 0012cd50 775f77e0 ole32!CClassCache::CDllPathEntry::CFinishObject::Finish+0x2f
0012cd3c 775047c8 0012ce70 0012cd5c 0012cd50 ole32!CClassCache::CFinishComposite::Finish+0x1d
0012ce8c 77503e09 77503f83 00469d0e 00147578 ole32!CClassCache::CleanUpDllsForProcess+0x1b2
0012ce90 77503f83 00469d0e 00147578 00000000 ole32!ProcessUninitialize+0x37
0012cea4 774f138e 0012cebc 00000000 003c41d0 ole32!wCoUninitialize+0x11b
0012cec0 0041c3b4 00490e60 00490e60 0012cf54 ole32!CoUninitialize+0x5b ;  2 
0012ced0 00469d41 003c41d0 00000000 0045d018 AVerQuick+0x1c3b4
0012cf54 0045cbcf 00000016 00000001 00478608 AVerQuick+0x69d41
0012cf74 0040c97f 00000016 00000001 00000000 AVerQuick+0x5cbcf
0012e474 0045bc0a 00000016 00000001 00000000 AVerQuick+0xc97f
0012e4d4 0045be25 003c41d0 00000000 00000016 AVerQuick+0x5bc0a
0012e4f4 7e368734 000100d6 00000016 00000001 AVerQuick+0x5be25
0012e520 7e368816 0045bdf1 000100d6 00000016 user32!InternalCallWinProc+0x28 ;  1 
0012e588 7e378ea0 00000000 0045bdf1 000100d6 user32!UserCallWinProcCheckWow+0x150
0012e5dc 7e378eec 006a44e0 00000016 00000001 user32!DispatchClientMessage+0xa3
0012e604 7c90e473 0012e614 00000018 006a44e0 user32!__fnDWORD+0x24
0012e628 7e3694be 7e378e0d 000100d6 0000003b ntdll!KiUserCallbackDispatcher+0x13
0012e67c 7e378dd9 000100d6 0000003b 00000009 user32!NtUserMessageCall+0xc
0012e698 7e378d77 000100d6 0000003b 00000009 user32!RealDefWindowProcW+0x47
0012e6e0 7e368734 000100d6 0000003b 00000009 user32!DefWindowProcW+0x72
0012e70c 7e368816 7e378d20 000100d6 0000003b user32!InternalCallWinProc+0x28
0012e774 7e37a013 00000000 7e378d20 000100d6 user32!UserCallWinProcCheckWow+0x150
0012e7a4 7e37a039 7e378d20 000100d6 0000003b user32!CallWindowProcAorW+0x98
0012e7c4 0045c5ce 7e378d20 000100d6 0000003b user32!CallWindowProcW+0x1b
0012e7e4 0045cbe6 0000003b 00000009 00000000 AVerQuick+0x5c5ce
0012e800 0040c97f 0000003b 00000009 00000000 AVerQuick+0x5cbe6
0012fd00 0045bc0a 0000003b 00000009 00000000 AVerQuick+0xc97f
0012fd60 0045be25 003c41d0 00000000 0000003b AVerQuick+0x5bc0a
0012fd80 7e368734 000100d6 0000003b 00000009 AVerQuick+0x5be25
0012fdac 7e368816 0045bdf1 000100d6 0000003b user32!InternalCallWinProc+0x28
0012fe14 7e378ea0 00000000 0045bdf1 000100d6 user32!UserCallWinProcCheckWow+0x150
0012fe68 7e378eec 006a44e0 0000003b 00000009 user32!DispatchClientMessage+0xa3
0012fe90 7c90e473 0012fea0 00000018 006a44e0 user32!__fnDWORD+0x24
0012feb4 7e3691be 7e3691f1 00490e90 00000000 ntdll!KiUserCallbackDispatcher+0x13
0012fed4 0045b7df 00490e90 00000000 00000000 user32!NtUserGetMessage+0xc
0012fef0 0045b327 00490e60 00490e60 0012ffc0 AVerQuick+0x5b7df
0012ff08 0045fb99 00490e60 0046159b 00380039 AVerQuick+0x5b327
0012ff10 0046159b 00380039 00000000 7ffd7000 AVerQuick+0x5fb99
0012ff20 00457a8c 00400000 00000000 0002096c AVerQuick+0x6159b
0012ff34 00443676 00400000 00000000 0002096c AVerQuick+0x57a8c
0012ffc0 7c817077 00380039 00320031 7ffd7000 AVerQuick+0x43676
0012fff0 00000000 00443597 00000000 78746341 kernel32!BaseProcessStart+0x23

   Информации из него почерпнуть можно много, поэтому начнем рассматривать ее последовательно.

    1  Первое, на что стоит обратить внимание - что поток получил сообщение о завершении работы системы (WM_ENDSESSION = 16h) и начал его обрабатывать.

   Из этого можно сделать вывод, что до этого поток получил сообщение WM_QUERYENDSESSION и ответил на него согласием.

    2  Идем дальше. В процессе обработки этого сообщения была вызвана функция CoUninitialize из ole32.dll для финализации библиотеки COM в текущем потоке, выгрузки всех библиотек и освобождения ресурсов.

    3  При финализации библиотеки COM была инициирована выгрузка динамической библиотеки GraphMaster.dll.

0:001> lm a 10000000
start    end        module name
10000000 1003a000   GraphMaster C (export symbols)       GraphMaster.dll

    4  Вызов DllMain (0x100148c0) библиотеки GraphMaster.dll с причиной вызова (dwReason) DLL_PROCESS_DETACH.

    5  Вызов SetUnhandledExceptionFilter для установки обработчика исключений верхнего уровня. Устанавливаемый обработчик принадлежит исполняемому образу приложения:

0:000> lm a 0044cff1 
start    end        module name
00400000 0049c000   AVerQuick C (no symbols) 

   Из этого можно сделать вывод, что перед нами восстановление ранее обработчика исключений верхнего уровня. Т.е. при загрузке GraphMaster.dll вызывает SetUnhandledExceptionFilter для установки своего обработчика (при этом получает адрес ранее установленного фильтра), а во время выгрузки - восстанавливает его.

    6  И, в конце концов, поток был заблокирован на критической секции, захваченной вторым потоком (как мы помним - в дампе два потока):

0:000> !cs 7c885780
-----------------------------------------
Critical section   = 0x7c885780 (kernel32!gcsUEFInfo+0x0)
DebugInfo          = 0x7c97e720
LOCKED
LockCount          = 0x1
OwningThread       = 0x00000230  ; thread #1
RecursionCount     = 0x1
LockSemaphore      = 0x138
SpinCount          = 0x00000000

   Очевидно, kernel32!gcsUEFInfo - это критическая секция, защищающая работу с фильтром исключений верхнего уровня.
   UEF - Unhandled Exception Filter

   И вот настал тот торжественный миг, когда вторая часть МБ (Марлезонского балета) становится неизбежной. Переходим к изучению стека второго потока:

0:001> kv
ChildEBP RetAddr  Args to Child              
00f2f6dc 7c90df5a 7c91b24b 000002a8 00000000 ntdll!KiFastSystemCallRet
00f2f6e0 7c91b24b 000002a8 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
00f2f768 7c901046 0197e178 7c912cce 7c97e178 ntdll!RtlpWaitForCriticalSection+0x132
00f2f770 7c912cce 7c97e178 00000000 00144438 ntdll!RtlEnterCriticalSection+0x46 ;  1 
00f2f7ac 7c80b4af 00000001 00000000 00f2f7e8 ntdll!LdrLockLoaderLock+0xea
00f2f804 7c863c85 10000000 00144444 00000104 kernel32!GetModuleFileNameW+0x89 ;  2  
00f2f840 7c864132 1001a102 00144438 00000000 kernel32!FillUEFInfo+0x51 ;  3 
00f2fab4 7c83ab50 00f2fadc 7c839b39 00f2fae4 kernel32!UnhandledExceptionFilter+0x168 ;  4 
00f2fabc 7c839b39 00f2fae4 00000000 00f2fae4 kernel32!BaseThreadStart+0x4d
00f2fae4 7c9032a8 00f2fbd0 00f2ffdc 00f2fbec kernel32!_except_handler3+0x61
00f2fb08 7c90327a 00f2fbd0 00f2ffdc 00f2fbec ntdll!ExecuteHandler2+0x26
00f2fbb8 7c90e48a 00000000 00f2fbec 00f2fbd0 ntdll!ExecuteHandler+0x24
00f2fbb8 00da2433 00000000 00f2fbec 00f2fbd0 ntdll!KiUserExceptionDispatcher+0xe
WARNING: Frame IP not in any known module. Following frames may be wrong.
00f2feb4 76b254e3 00000010 00000000 00dc3b18 <Unloaded_AVERAPI.dll>+0x2433
00f2fedc 76b3adfe 00da2433 00000003 00000010 winmm!DriverCallback+0x5c
00f2ff18 76b3af02 00000010 cccccccc 8a42db0c winmm!TimerCompletion+0xf4
00f2ffb4 7c80b729 00000000 cccccccc cccccccc winmm!timeThread+0x53
00f2ffec 00000000 76b3aeaf 00000000 00000000 kernel32!BaseThreadStart+0x37

   Здесь тоже есть над чем помедитировать, поэтому и этот стек будем рассматривать последовательно. Но на этот раз с другой стороны :)

    1  Этот поток заблокирован на критической секции:

0:000> !cs 7c97e178
-----------------------------------------
Critical section   = 0x7c97e178 (ntdll!LdrpLoaderLock+0x0)
DebugInfo          = 0x7c97e1a0
LOCKED
LockCount          = 0x1
OwningThread       = 0x00000794  ; thread #0
RecursionCount     = 0x1
LockSemaphore      = 0x2A8
SpinCount          = 0x00000000

   Выясняется, что критичечкая секция, на которой заблокирован второй потока - критическая секция загрузчика и владеет ей основной поток. Собстсвенно тут нет ничего неожиданного, т.к. мы помним, что основной поток в данный момен находится "в недрах" DllMain библиотеки GraphMaster.dll - а эти вызовы защищаются блокировкой LdrpLoaderLock.

    2  А попытка захвата критической секции загрузчика была предпринята вследствие вызова функции GetModuleFileNameW для получения полного пути к файлу, содержащему модуль 10000000 (по этому адресу загружена уже небезизвестная нам динамическая библиотеке GraphMaster.dll).

    3  Перед этим была вызвана внутренняя функция kernel32 FillUEFInfo (UEF - Unhandled Exception Filter) для, как следует из ее названия, получения информации о текущем фильтре исключений верхнего уровня. Коим, очевидно, является обработчик, установленный библиотекой GraphMaster.

    4  Вызов фунции UnhandledExceptionFilter вследствие возникновения необработанного исключения в потоке.

   Первый парамерт этой функции - указатель на структуру EXCEPTION_POINTERS. Его можно раскрыть и посмотреть на Exception Record и Exception Context:

0:001> .exptr 00f2fadc 

----- Exception record at 00f2fbd0:
ExceptionAddress: 00da2433 (<Unloaded_AVERAPI.dll>+0x00002433)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 00000000
   Parameter[1]: 00da2433
Attempt to read from address 00da2433

----- Context record at 00f2fbec:
eax=00000000 ebx=00000000 ecx=00f2fee8 edx=76b40200 esi=00000010 edi=00da2433
eip=00da2433 esp=00f2feb8 ebp=00f2fedc iopl=0         nv up ei pl zr na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00010246
<Unloaded_AVERAPI.dll>+0x2433:
00da2433 ??              ???

   И стек в момет возникновения исключения:

WARNING: Frame IP not in any known module. Following frames may be wrong.
00f2feb4 76b254e3 <Unloaded_AVERAPI.dll>+0x2433
00f2fedc 76b3adfe winmm!DriverCallback+0x5c
00f2ff18 76b3af02 winmm!TimerCompletion+0xf4
00f2ffb4 7c80b729 winmm!timeThread+0x53
00f2ffec 00000000 kernel32!BaseThreadStart+0x37

   Делаем вывод: исключение произошло вследствие вызова функции отключенной от адресного пространства (то бишь выгруженной) динамической библиотеки AVERAPI.dll (а выгружена эта библиотека, скорее всего, была в ходе все той же очистки, инициированной главным потоком):

0:001> lm
start    end        module name
...
Unloaded modules:
5b830000 5b842000   kstvtune.ax
581c0000 581cd000   ksxbar.ax
74940000 74a63000   msxml3.dll
00dd0000 00df1000   M15C.dll
00e00000 00e0f000   MsgLog.DLL
00da0000 00db8000   AVERAPI.dll
6d3a0000 6d3d9000   DINPUT8.dll
68f90000 68fb3000   ksproxy.ax
5ef80000 5ef84000   ksuser.dll
765b0000 765c1000   devenum.dll
00c80000 00c94000   MVDetection.ax
581d0000 581e9000   kswdmcap.ax
73d90000 73e81000   MFC42.DLL
61ec0000 61ece000   MFC42LOC.DLL
75870000 7587a000   vidcap.ax
76b00000 76b11000   ATL.DLL 

   Подведем итоги.

   Thread #0.
   При обработке сообщения WM_ENDSESSION основной поток приложения начинает очистку. На одном из этапов этой очистки вызывается финализация библиотеки COM. Вследствие этого система инициирует выгрузку GraphMaster.dll (одна из COM-библиотек), которая получает уведомление DLL_PROCESS_DETACH в DllMain после захвата критической секции загрузчика. В DllMain, для восстановления фильтра исключений верхнего уровня (измененного ранее при загрузке и получении уведомления DLL_PROCESS_ATTACH) вызывается функция SetUnhandledExceptionFilter. После чего поток блокируется на критической секции gcsUEFInfo.

   Thread #1.
   Во втором потоке возникает исключения вследствие вызова функции выгруженной библиотеки AVERAPI.dll. При его обработке диспетчер SEH не находит обработчиков для него и передает управление фунции UnhandledExceptionFilter. Одной из задач этой функции является вызов фильтра исключений верхнего уровня (если таковой был уставлен). Для этого сначала захватывается критическая секция gcsUEFInfo, после чего вызывается внутренняя функция FillUEFInfo для получения информации о текущем фильтре исключений верхнего уровня. Внутри этой функции при вызове функции GetModuleFileNameW поток блокируется на критической секции загрузчика.

   Итог: классический deadlock.

   P.S..
   Информация о версиях исполняемых файлов:

Versions:
  AVerQuick.exe:     1.1.2.20
  GraphMaster.dll:   2.1.0.1
  AVerAPI.dll:       7.1.0.7

Ссылки
[1] WM_QUERYENDSESSION и WM_ENDSESSION (Windows Shutdown)
[2] Как создать дамп процесса