Linphone SDK 5.2.114 иногда зависает при завершении аудиопотока, отладка ядра Windbg обнаружила зависание USB ZwDeviceIoControlFile.

Question

При использовании линфон SDK 5.2.114 я заметил, что он иногда зависает на компьютере клиента с Windows 7, когда используется USB-гарнитура, в момент, когда SIP-звонок переходит в режим удержания (только для получения). SDK пытается завершить аудиопоток в этом событии.

Я нашел строку кода, где происходит зависание, добавив логирование и перекомпилировав SDK. Это происходит в mswasapi_reader.cpp, MSWASAPIReader::~MSWASAPIReader() { RELEASE_CLIENT(mAudioClient); …}

С некоторыми усилиями мне удалось воспроизвести это на виртуальной машине с Windows 7, также используя USB-гарнитуру. Частота зависания составляет одно зависание после 1500–3000 звонков.

Когда происходит зависание, операционная система становится безмолвной, регулировка системной громкости не дает звука, аудиофайлы не воспроизводятся, и запись аудио невозможна. Проблема решается после того, как USB-гарнитура будет отключена и снова подключена.

Я сделал дамп памяти, и стек вызовов выглядит так:

0: kd:x86> kb
  *** Стек вызовов для последнего установленного контекста - .thread/.cxr сбрасывает его
 # ChildEBP          RetAddr               Args to Child                                         
00 0c39d37c 76227653     00000504 40020000 068009f8 ntdll_77780000!ZwAlpcSendWaitReceivePort+0x12
01 0c39d3b0 76227ad0     00020000 068009f8 055ca258 RPCRT4!LRPC_CASSOCIATION::AlpcSendWaitReceivePort+0x5d
02 0c39d408 762279d3     0c39d478 055ca1a0 0c39d894 RPCRT4!LRPC_BASE_CCALL::DoSendReceive+0xa3
03 0c39d420 76232358     0c39d478 0c39d4a4 0c39d440 RPCRT4!LRPC_BASE_CCALL::SendReceive+0x2f
04 0c39d430 76227401     0c39d478 0c39d4a4 0c39d454 RPCRT4!LRPC_CCALL::SendReceive+0x25
05 0c39d440 7622809b     0c39d478 6e957a00 00000001 RPCRT4!I_RpcSendReceive+0x28
06 0c39d454 7622806a     0c39d4a4 06800a80 762c0149 RPCRT4!NdrSendReceive+0x31
07 0c39d460 762c0149     85186b4e 00000000 0c39d8fc RPCRT4!NdrpSendReceive+0x9
08 0c39d874 6e95d56a     6e957a00 6e9567ba 0c39d894 RPCRT4!NdrClientCall2+0x1a6
09 0c39d88c 6e95d511     0e3e92dc 001a3ec0 00000000 AUDIOSES!AudioServerDestroyStream+0x19
0a 0c39d8dc 6e95d4a3     0c39d8fc 00000000 0e3e9278 AUDIOSES!CAudioClient::DestroyRemoteStream+0x62
0b 0c39d928 6e95d257     0e3e9278 6e95d20b 0e3e9278 AUDIOSES!CAudioClient::FinalRelease+0xd8
0c 0c39d930 6e95d20b     0e3e9278 0c39d950 6e95d1f1 AUDIOSES!ATL::CComObject<CAudioClient>::~CComObject<CAudioClient>+0x33
0d 0c39d93c 6e95d1f1     00000001 0de10900 06a28fc8 AUDIOSES!ATL::CComObject<CAudioClient>::`scalar deleting destructor'+0xd
*** ПРЕДУПРЕЖДЕНИЕ: Невозможно проверить контрольную сумму для libmswasapi.dll
0e 0c39d950 688e3d2c     0e3e9278 42ab2025 06a28fc8 AUDIOSES!ATL::CComObject<CAudioClient>::Release+0x27
WARNING: Информация о разворачивании стека недоступна. Последующие кадры могут быть неверными.
0f 0c39d970 688e3e1b     10510cf0 0c39d988 688e3e50 libmswasapi+0x3d2c
10 0c39d97c 688e3e50     00000001 0c39d99c 688e16ee libmswasapi+0x3e1b
11 0c39d988 688e16ee     06a28fc8 688ec4d4 10510cf0 libmswasapi+0x3e50
*** ПРЕДУПРЕЖДЕНИЕ: Невозможно проверить контрольную сумму для mediastreamer.dll
12 0c39d99c 69dba6e4     10510cf0 0de10900 0de10900 libmswasapi+0x16ee
13 0c39d9b0 69dd3124     10510cf0 008bae98 0c39d9dc mediastreamer!ms_filter_destroy+0x14
14 0c39d9c0 69dd5dc3     0de10900 0f89d270 00000000 mediastreamer!audio_stream_force_software_echo_canceller+0x54
*** ПРЕДУПРЕЖДЕНИЕ: Невозможно проверить контрольную сумму для liblinphone.DLL
15 0c39d9dc 6a16bce0     0de10900 42aa3257 0decf110 mediastreamer!audio_stream_stop+0x3d3
16 0c39da0c 6a15d441     42aa3263 10435690 0a6eb888 liblinphone+0x19bce0
17 0c39da38 6a1515d8     0278bc68 6a250f6f 42aa3233 liblinphone+0x18d441
18 0c39da68 6a1c7961     0278bc68 0a4be790 0278bc68 liblinphone+0x1815d8
19 0c39da84 6a1cc188     0fd96d90 000000c8 10435690 liblinphone+0x1f7961
1a 0c39db1c 6a1e0b14     0278bc68 0c39dbc8 42aa33cf liblinphone+0x1fc188
*** ПРЕДУПРЕЖДЕНИЕ: Невозможно проверить контрольную сумму для bellesip.dll
1b 0c39db94 68c25fd5     068e5de4 0c39dbc8 0c39dbd8 liblinphone+0x210b14
1c 0c39dba4 68c214ac     069649e0 0c39dbc8 069649e0 bellesip!process_request_event+0x15 [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\siplistener.c @ 96] 
1d 0c39dbd8 68c2113a     06915a38 10435690 06915a38 bellesip!belle_sip_provider_dispatch_request+0x29c [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\provider.c @ 184] 
1e 0c39dbf0 68c1f943     06915a38 10435690 0c39dc28 bellesip!belle_sip_provider_dispatch_message+0x2a [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\provider.c @ 301] 
1f 0c39dc00 68c031cd     06915a38 0ab48d00 10435690 bellesip!channel_on_message+0x33 [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\provider.c @ 451] 
20 0c39dc28 68c014cb     0ab48d00 00000278 0ab48ddc bellesip!notify_incoming_messages+0x5d [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\channel.c @ 531] 
21 0c39dc3c 68c0136c     0ab48d00 00000000 00000001 bellesip!belle_sip_channel_process_stream+0x7b [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\channel.c @ 644] 
22 0c39dc58 68c01252     0ab6a638 06cd6e98 0ab48d00 bellesip!belle_sip_channel_process_read_data+0xcc [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\channel.c @ 682] 
23 0c39dc6c 68c2ac50     0ab48d00 00000001 055161b8 bellesip!belle_sip_channel_process_data+0x22 [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\channel.c @ 707] 
24 0c39ed2c 68bf5fe3     06cd6e98 00000001 06937440 bellesip!on_udp_data+0x140 [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\transports\udp_listeningpoint.c @ 207] 
25 0c39ed70 68bf63d6     06937440 053d4a60 0c39eda8 bellesip!belle_sip_main_loop_iterate+0x2c3 [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\belle_sip_loop.c @ 697] 
26 0c39ed80 68bf6424     06937440 06937440 68be532b bellesip!belle_sip_main_loop_run+0x36 [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\belle_sip_loop.c @ 753] 
27 0c39eda8 68c27101     06937440 00000000 0c39edf0 bellesip!belle_sip_main_loop_sleep+0x24 [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\belle_sip_loop.c @ 767] 
28 0c39edb8 6a275711     06903278 00000000 0c39ee00 bellesip!belle_sip_stack_sleep+0x11 [c:\gitlab-runner\builds\hexp7jis\2\bc\public\linphone-sdk\belle-sip\src\sipstack.c @ 323] 
29 0c39edf0 05714b8e     00000000 89bfe8ca 70b3aeb0 liblinphone+0x2a5711
2a 0c39ee44 7006ac59     00000000 02d1bda4 0c39ee84 0x5714b8e
2b 0c39ee54 0803ec7c     00000000 00000000 02f58f50 System_Private_CoreLib!System.Threading.ThreadHelper.ThreadStart_Context(System.Object)$##6001CC1+0x41
2c 0c39ee84 7009328f     02f58f78 0c39eeb0 06630128 0x803ec7c
2d 0c39ee98 708ca05f     00000008 0c39ef3c 7084fe61 System_Private_CoreLib!System.Threading.ThreadHelper.ThreadStart()$##6001CC4+0x23
2e 0c39eea4 7084fe61     0c39ef10 0c39f0a4 708711d0 coreclr!CallDescrWorkerInternal+0x34 [D:\a\_work\1\s\src\vm\i386\asmhelpers.asm @ 615] 
2f (Inline) --------     -------- -------- -------- coreclr!CallDescrWorkerWithHandler+0x55 [d:\a\_work\1\s\src\vm\callhelpers.cpp @ 70] 
30 0c39ef3c 708bc222     0c39ef88 00000000 00000000 coreclr!MethodDescCallSite::CallTargetWorker+0x167 [d:\a\_work\1\s\src\vm\callhelpers.cpp @ 604] 
31 0c39f014 7084db5b     0c39f15c 8586b916 0c39f144 coreclr!ThreadNative::KickOffThread_Worker+0xf2 [d:\a\_work\1\s\src\vm\comsynchronizable.cpp @ 248] 
32 (Inline) --------     -------- -------- -------- coreclr!ManagedThreadBase_DispatchInner+0x93 [d:\a\_work\1\s\src\vm\threads.cpp @ 7466] 
33 0c39f0b0 7084da3a     8586b8be 0c39f120 06630128 coreclr!ManagedThreadBase_DispatchMiddle+0xe0 [d:\a\_work\1\s\src\vm\threads.cpp @ 7510] 
34 0c39f118 707c295c     8586b832 707c2870 0ab2fe38 coreclr!ManagedThreadBase_DispatchOuter+0x78 [d:\a\_work\1\s\src\vm\threads.cpp @ 7696] 
35 (Inline) --------     -------- -------- -------- coreclr!ManagedThreadBase_FullTransition+0x1c [d:\a\_work\1\s\src\vm\threads.cpp @ 7722] 
36 (Inline) --------     -------- -------- -------- coreclr!ManagedThreadBase::KickOff+0x1c [d:\a\_work\1\s\src\vm\threads.cpp @ 7757] 
37 0c39f194 707c2850     0ab2fe38 0c39f270 7bb14e32 coreclr!ThreadNative::KickOffThread+0xec [d:\a\_work\1\s\src\vm\comsynchronizable.cpp @ 363] 
38 0c39f9ac 753e386d     0274f5f0 0c39f9f8 777b96f2 coreclr!Thread::intermediateThreadProc+0x50 [d:\a\_work\1\s\src\vm\threads.cpp @ 2110] 
39 0c39f9b8 777b96f2     0274f5f0 7bb1462a 00000000 kernel32!BaseThreadInitThunk+0xe
3a 0c39f9f8 777b96c5     707c2800 0274f5f0 00000000 ntdll_77780000!__RtlUserThreadStart+0x70
3b 0c39fa10 00000000     707c2800 0274f5f0 00000000 ntdll_77780000!_RtlUserThreadStart+0x1b

Я также провел отладку ядра Windows, используя команды !process, !alpc и !thread. После промежуточного svchost.exe я обнаружил, что зависание происходит на ZwDeviceIoControlFile audiodg.exe.

THREAD fffffa8034a509e0  Cid 07c0.124c  Teb: 000000007ef91000 Win32Thread: fffff900c07e0c00 WAIT: (WrLpcReply) UserMode Non-Alertable
            fffffa8034a50da8  Semaphore Limit 0x1
        Ожидание ответа на ALPC-сообщение fffff8a00ade09d0: в очереди на порту fffffa803326ce60: принадлежит процессу fffffa8032f02b00
        Не совершая представления
        DeviceMap                 fffff8a00122f150
        Владельческий процесс        fffffa80335a8b00       Изображение:         CPFCcodSipPhone.exe
        Присоединенный процесс      N/A            Изображение:         N/A
        Ожидание начального TickCount      9306801        Такты: 37278 (0:00:09:41.540)
        Количество переключений контекста      9605818        Идеальный процессор: 0                 Большой стек
        Время пользователем             00:07:07.458
        Время в ядре               00:01:02.618

0: kd> !alpc /m fffffa803326ce60
…

THREAD fffffa8033bcb940  Cid 0d54.1310  Teb: 000007fffff98000 Win32Thread: fffff900c07d1c00 WAIT: (Executive) KernelMode Non-Alertable
            fffffa803147ed38  NotificationEvent
        IRP List:
            fffffa8031665c60: (0006,03a0) Flags: 00060000  Mdl: 00000000
            fffffa803133f100: (0006,03a0) Flags: 00060030  Mdl: 00000000
        Не совершая представления
        DeviceMap                 fffff8a0027af5f0
        Владельческий процесс        fffffa80333f1240       Изображение:         audiodg.exe
        Присоединенный процесс      N/A            Изображение:         N/A
        Ожидание начального TickCount      9306803        Такты: 37276 (0:00:09:41.509)
        Количество переключений контекста      1074           Идеальный процессор: 1                 Большой стек
        Время пользователем             00:00:00.031
        Время в ядре               00:00:00.046
        Win32 Start Address ntdll!TppWorkerThread (0x00000000776b8b50)
        Стек Init fffff88009dedc70 Текущий fffff88009decab0
        База fffff88009dee000 Лимит fffff88009de7000 Вызов 0000000000000000
        Приоритет 8 Базовый приоритет 8 Снижение приоритета 0 IoPriority 2 PagePriority 5
        Child-SP          RetAddr               Call Site
        fffff880`09decaf0 fffff800`03e59602     nt!KiSwapContext+0x7a
        fffff880`09decc30 fffff800`03e560b3     nt!KiCommitThreadWait+0x1d2
        fffff880`09deccc0 fffff880`058062e9     nt!KeWaitForSingleObject+0x1a3
        fffff880`09decd60 fffff880`05826307     USBPORT+0x62e9
        fffff880`09decdb0 fffff880`058265f9     USBPORT+0x26307
        fffff880`09dece10 fffff880`0582e485     USBPORT+0x265f9
        fffff880`09dece40 fffff880`0582287c     USBPORT!USBPORT_RegisterUSBPortDriver+0x501d
        fffff880`09decee0 fffff880`0582b1a8     USBPORT+0x2287c
        fffff880`09decf90 fffff880`05804ae0     USBPORT!USBPORT_RegisterUSBPortDriver+0x1d40
        fffff880`09decfd0 fffff880`05b895fd     USBPORT+0x4ae0
        fffff880`09ded010 fffff880`05bba0e7     usbhub+0x35fd
        fffff880`09ded040 fffff880`05b87fb7     usbhub+0x340e7
        fffff880`09ded090 fffff880`062d8960     usbhub+0x1fb7
        fffff880`09ded0c0 fffff880`062d8b4a     usbccgp+0x3960
        fffff880`09ded100 fffff880`062d672e     usbccgp+0x3b4a
        fffff880`09ded130 fffff880`03753828     usbccgp+0x172e
        fffff880`09ded1b0 fffff880`037540ff     usbaudio+0x13828
        fffff880`09ded240 fffff880`037438dd     usbaudio+0x140ff
        fffff880`09ded2a0 fffff880`0374d419     usbaudio+0x38dd
        fffff880`09ded300 fffff880`05b4f068     usbaudio+0xd419
        fffff880`09ded330 fffff880`05b4e939     ks!CKsPin::ClientSetDeviceState+0x148
        fffff880`09ded370 fffff880`05b4e103     ks!CKsPipeSection::DistributeStateChangeToPins+0xd9
        fffff880`09ded3b0 fffff880`05b4ea67     ks!CKsQueue::SetDeviceState+0xa3
        fffff880`09ded400 fffff880`05b4e761     ks!CKsPipeSection::DistributeDeviceStateChange+0xab
        fffff880`09ded460 fffff880`05b4f715     ks!CKsPipeSection::SetDeviceState+0x281
        fffff880`09ded4c0 fffff880`05b4b59b     ks!CKsPin::Property_ConnectionState+0x229
        fffff880`09ded510 fffff880`05b4bb37     ks!KspPropertyHandler+0x72b
        fffff880`09ded570 fffff880`05b4c173     ks!KspHandleAutomationIoControl+0x2c7
        fffff880`09ded5f0 fffff880`05b4b7ab     ks!CKsPin::DispatchDeviceIoControl+0x11f
        fffff880`09ded650 fffff880`05b32560     ks!KsDispatchIrp+0xdb
        fffff880`09ded680 fffff880`0627e674     ks!CKsDevice::PassThroughIrp+0xc0
        fffff880`09ded6c0 fffff880`0627bc21     ksthunk!CKernelFilterDevice::SynchronousForwardIrp+0x70
        fffff880`09ded720 fffff880`0627ba87     ksthunk!CKSThunkDevice::CheckIrpForStackAdjustmentNative+0x171
        fffff880`09ded7c0 fffff880`0627b79b     ksthunk!CKSThunkDevice::DispatchIoctl+0xcf
        fffff880`09ded7f0 fffff800`040f66ba     ksthunk!CKernelFilterDevice::DispatchIrp+0x93
        fffff880`09ded850 fffff800`042cf8d1     nt!IopSynchronousServiceTail+0xfa
        fffff880`09ded8c0 fffff800`0415c226     nt!IopXxxControlFile+0xc51
        fffff880`09deda00 fffff800`03ebd443     nt!NtDeviceIoControlFile+0x56
        fffff880`09deda70 00000000`77628b3a     nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffff880`09dedae0)
        00000000`022ddb18 00000000`00000000     ntdll!ZwDeviceIoControlFile+0xa

Так что же является причиной зависания, и как я могу это решить?

Я нашел, что кто-то говорил, что инициализация IAudioClient и освобождение IAudioClient должны происходить в одном потоке, иначе это может зависнуть иногда. Я изменил некоторый код SDK, используя doLater() для выполнения вызова accept(), что делает инициализацию и освобождение в одном потоке. Я ожидал, что это решит проблему, но безуспешно, зависание все еще происходит.

Linphone SDK 5.2.114 иногда зависает при завершении аудиопотока, отладка ядра Windbg обнаружила зависание USB ZwDeviceIoControlFile.

Вопрос или проблема

Ответ или решение

Причины зависания

Решение проблемы

Заключение