Closed Bug 1572273 Opened 5 years ago Closed 4 years ago

Sound is gone when unplugging the input device during WebRTC

Categories

(Core :: Audio/Video: cubeb, defect, P2)

Product:
Core
Component:
Audio/Video: cubeb
Platform:
Unspecified
macOS
Type:
defect

Tracking

()

Status:
RESOLVED FIXED

People

(Reporter: chunmin, Assigned: chunmin)

References

Details

Attachments

(2 files)

backtrace_all_threads.txt
163.82 KB, text/plain
Details
GitHub Pull Request
43 bytes, text/x-github-pull-request
Details | Review

This only happen when the default input device is set to some certain device. In my case, the problem can be reproduced with e-Kit MIC-U01 but cannot be reproduced with Plantronic .Audio 628.

Step to reproduce

  1. Set the system default input device to an input-only USB device D (e.g., e-Kit MIC-U01)
  2. Make a WebRTC call on computer A
  3. Use device B to join the WebRTC call
  4. Unplug the input device D

Expect

I can still hear the sound from device B via the my output device

Actual

No sound can be heard anymore

It seems it only happens in C backend. The Rust backend works fine. I haven't found the root cause so I don't know why Rust backend can work.

It might be a deadlock issue. The camera can still work. However, the sound cannot be heard from the output device anymore. Not sure if it's possible to keep camera alive when the audio thread is locked.

The output callback thread always stops at here and reinit thread always stops at here then here. It looks like the mutex inside the input AudioUnit is hold by something, but that's just my guess.

(In reply to C.M.Chang[:chunmin] from comment #1)

It might be a deadlock issue. The camera can still work. However, the sound cannot be heard from the output device anymore. Not sure if it's possible to keep camera alive when the audio thread is locked.

It is nowadays. We still need the audio thread to connect media elements to the video track (adding a listener) and the like, but once set up, frames can flow without it.

Can you please try removing the AudioOutputUnitStop() call in [1] to verify that the problem lies in there? The reinit will stop the stream anyway. It is strange that we get a reinit and a drain at the same time. It would be interesting to know which one comes first.

[1] https://searchfox.org/mozilla-central/rev/9775cca0a10a9b5c5f4e15c8f7b3eff5bf91bbd0/media/libcubeb/src/cubeb_audiounit.cpp#618

(In reply to Alex Chronopoulos [:achronop] from comment #3)

Can you please try removing the AudioOutputUnitStop() call in [1] to verify that the problem lies in there?

The problem is gone after removing the AudioOutputUnitStop(stm->input_unit) in that line.

It would be interesting to know which one comes first.

In my case, reinit always comes first and stop when calling AudioOutputUnitStop(stm->input_unit) in audiounit_stream_stop_internal then output callback comes later.

The problem is gone if I don't use the aggregate device by commenting these lines. The reason I tried not using the aggregate device is because I guess we have a deadlock between two mutexes inside the CoreAudio library. I'll explain the deadlock I observed in the later comment.

I used lldb to monitor the threads when the problem happened. There are four threads waiting for the mutex.

thread #46: tid = 0x5c844, 0x00007fff729aff06 libsystem_kernel.dylib`__psynch_mutexwait + 10, queue = 'org.mozilla.cubeb'
thread #47: tid = 0x5c893, 0x00007fff729aff06 libsystem_kernel.dylib`__psynch_mutexwait + 10, queue = 'com.apple.audio.CADispatchQueue.SerialQueue'
thread #77: tid = 0x5c990, 0x00007fff729aff06 libsystem_kernel.dylib`__psynch_mutexwait + 10, name = 'com.apple.audio.IOThread.client'
thread #78: tid = 0x5c9a4, 0x00007fff729aff06 libsystem_kernel.dylib`__psynch_mutexwait + 10, name = 'CubebOp~tion #2'
  1. thread #46 is a reinit thread, which is waiting for a CAMutex
  2. thread #47 is an internal thread fired for hardware property changed, which is waiting for a HALB_Mutex
  3. thread #77 is a Output callback thread, which is waiting for a CAMutex
  4. thread #78 is a task thread of AsyncCubebOperation from GraphDriver, which is waiting for a owned_critical_section

Here is my hypothesis after checking their stacks.

  1. thread #46 holds a mutex for cubeb context, which is the mutex thread #78 is waiting for.
  2. thread #46 is waiting for a CAMutex, which is tied to input AudioUnit.
  3. From my past experience, there should a mutex for an AudioUnit. The mutex will be held when the data callback tied to the AudioUnit is running.
  4. thread #77 is waiting for a CAMutex, which is tied to input AudioUnit
  5. By 2, thread #77 also hold a CAMutex tied to output AudioUnit so that's why AudioOutputUnitStop(stm->output_unit) works fine.
  6. The CAMutex tied to input AudioUnit is held by something since thread #46 and thread #77 are waiting for it.
  7. HALB_Mutex is held by something since thread #47 is waiting for it.
  8. If there is a deadlock exist among these four threads, it's reasonable to believe that thread #47 holds the CAMutex tied to input AudioUnit and thread #77 holds the HALB_Mutex

In this case, the input device and output device are different, so they are merged into one aggregate device. If HAL means hardware abstraction layer here, the hardware is likely to be referred to the created aggregate device. The created aggregate device is assigned to the device of the input and output AudioUnit in our code, hence it makes sense to guess the HALB_Mutex tied to the aggregate device is held when the output callback (thread #77) is running. Another reason to believe is that the problem is gone by not using the aggregate device (comment 5). I guess it is because the HALB_Mutex tied to the hardware are different for input and output when the input device and output device are separate.

Stacks of these four threads

Thread 46 (Reinit thread)

* thread #46, queue = 'org.mozilla.cubeb'
  * frame #0: 0x00007fff729aff06 libsystem_kernel.dylib`__psynch_mutexwait + 10
    frame #1: 0x00007fff72a66d52 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 96
    frame #2: 0x00007fff72a644cd libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 222
    frame #3: 0x000000018de0ae75 CoreAudio`CAMutex::Lock() + 67
    frame #4: 0x000000018df2fef3 CoreAudio`AUMethodStop(void*) + 39
    frame #5: 0x0000000119ff7899 XUL`::___ZL29audiounit_reinit_stream_asyncP12cubeb_streamj_block_invoke_2() [inlined] audiounit_stream_stop_internal(stm=<unavailable>) at cubeb_audiounit.cpp:2945:9 [opt]
    frame #6: 0x0000000119ff7888 XUL`::___ZL29audiounit_reinit_stream_asyncP12cubeb_streamj_block_invoke_2() [inlined] audiounit_reinit_stream(stm=0x0000000108354c00, flags=3) at cubeb_audiounit.cpp:806 [opt]
    frame #7: 0x0000000119ff783e XUL`::___ZL29audiounit_reinit_stream_asyncP12cubeb_streamj_block_invoke_2(.block_descriptor=0x0000000165dcf220) at cubeb_audiounit.cpp:894 [opt]
    frame #8: 0x00007fff7282a5f8 libdispatch.dylib`_dispatch_call_block_and_release + 12
    frame #9: 0x00007fff7282b63d libdispatch.dylib`_dispatch_client_callout + 8
    frame #10: 0x00007fff728318e0 libdispatch.dylib`_dispatch_lane_serial_drain + 602
    frame #11: 0x00007fff72832396 libdispatch.dylib`_dispatch_lane_invoke + 385
    frame #12: 0x00007fff7283a6ed libdispatch.dylib`_dispatch_workloop_worker_thread + 598
    frame #13: 0x00007fff72a65611 libsystem_pthread.dylib`_pthread_wqthread + 421
    frame #14: 0x00007fff72a653fd libsystem_pthread.dylib`start_wqthread + 13

Thread 47 (Property Changed from HAL, it’s a internal thread we won’t touch)

* thread #47, queue = 'com.apple.audio.CADispatchQueue.SerialQueue'
  * frame #0: 0x00007fff729aff06 libsystem_kernel.dylib`__psynch_mutexwait + 10
    frame #1: 0x00007fff72a66d52 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 96
    frame #2: 0x00007fff72a644cd libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 222
    frame #3: 0x00007fff45e45068 CoreAudio`HALB_Mutex::Lock() + 92
    frame #4: 0x00007fff45e7aa3f CoreAudio`HALC_ProxyIOContext::StopIOProc(int (*)(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)) + 43
    frame #5: 0x00007fff45e7a937 CoreAudio`HALC_ShellDevice::StopIOProc(int (*)(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)) + 75
    frame #6: 0x00007fff45e7a6c4 CoreAudio`HAL_HardwarePlugIn_DeviceStop(AudioHardwarePlugInInterface**, unsigned int, int (*)(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)) + 181
    frame #7: 0x00007fff45e7a4f5 CoreAudio`HALPlugIn::DeviceStopIOProc(HALObject const&, int (*)(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)) + 41
    frame #8: 0x00007fff45e7a4aa CoreAudio`HALDevice::StopIOProc(int (*)(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)) + 200
    frame #9: 0x00007fff45e7a0dd CoreAudio`AudioDeviceStop + 103
    frame #10: 0x000000018de0f120 CoreAudio`AUHAL::StopHardware(bool) + 60
    frame #11: 0x000000018de0f2c5 CoreAudio`AUHAL::Stop() + 161
    frame #12: 0x000000018de02bdb CoreAudio`AUHAL::SelectDevice(unsigned int) + 553
    frame #13: 0x000000018de0dad9 CoreAudio`AUHAL::DeviceListener(unsigned int, unsigned int, AudioObjectPropertyAddress const*, void*) + 569
    frame #14: 0x00007fff45e6793e CoreAudio`HALPropertyListener::Call(unsigned int, unsigned int, AudioObjectPropertyAddress const*) + 282
    frame #15: 0x00007fff45e5bec8 CoreAudio`HALObject::PropertiesChanged(unsigned int, AudioObjectPropertyAddress const*) + 1280
    frame #16: 0x00007fff45e6073f CoreAudio`HALDevice::PropertiesChanged(unsigned int, AudioObjectPropertyAddress const*) + 421
    frame #17: 0x00007fff45e7848b CoreAudio`HALSystem::AudioObjectPropertiesChanged(AudioHardwarePlugInInterface**, unsigned int, unsigned int, AudioObjectPropertyAddress const*) + 163
    frame #18: 0x00007fff45e788d0 CoreAudio`_SendPropertiesChanged(void*) + 41
    frame #19: 0x00007fff7282b63d libdispatch.dylib`_dispatch_client_callout + 8
    frame #20: 0x00007fff728318e0 libdispatch.dylib`_dispatch_lane_serial_drain + 602
    frame #21: 0x00007fff72832396 libdispatch.dylib`_dispatch_lane_invoke + 385
    frame #22: 0x00007fff7283a6ed libdispatch.dylib`_dispatch_workloop_worker_thread + 598
    frame #23: 0x00007fff72a65611 libsystem_pthread.dylib`_pthread_wqthread + 421
    frame #24: 0x00007fff72a653fd libsystem_pthread.dylib`start_wqthread + 13

Thread 77 (Output callback)

* thread #77, name = 'com.apple.audio.IOThread.client'
  * frame #0: 0x00007fff729aff06 libsystem_kernel.dylib`__psynch_mutexwait + 10
    frame #1: 0x00007fff72a66d52 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 96
    frame #2: 0x00007fff72a644cd libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 222
    frame #3: 0x000000018de0ae75 CoreAudio`CAMutex::Lock() + 67
    frame #4: 0x000000018df2fef3 CoreAudio`AUMethodStop(void*) + 39
    frame #5: 0x0000000119ff8294 XUL`audiounit_output_callback(user_ptr=0x0000000108354c00, (null)=<unavailable>, tstamp=<unavailable>, bus=<unavailable>, output_frames=512, outBufferList=0x000000018ef26720) at cubeb_audiounit.cpp:618:11 [opt]
    frame #6: 0x000000018de0cb0f CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int) + 729
    frame #7: 0x000000018df28647 CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&) + 169
    frame #8: 0x000000018df27da7 CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&) + 601
    frame #9: 0x000000018de0ec96 CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*) + 1704
    frame #10: 0x00007fff45e76ed3 CoreAudio`HALC_ProxyIOContext::IOWorkLoop() + 3885
    frame #11: 0x00007fff45e75df4 CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*) + 122
    frame #12: 0x00007fff45e75956 CoreAudio`HALB_IOThread::Entry(void*) + 72
    frame #13: 0x00007fff72a662eb libsystem_pthread.dylib`_pthread_body + 126
    frame #14: 0x00007fff72a69249 libsystem_pthread.dylib`_pthread_start + 66
    frame #15: 0x00007fff72a6540d libsystem_pthread.dylib`thread_start + 13

Thread 78 (AsyncCubebOperation)

* thread #78, name = 'CubebOp~tion #2'
  * frame #0: 0x00007fff729aff06 libsystem_kernel.dylib`__psynch_mutexwait + 10
    frame #1: 0x00007fff72a66d52 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 96
    frame #2: 0x00007fff72a644cd libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 222
    frame #3: 0x0000000119ff1539 XUL`audiounit_stream_stop(cubeb_stream*) [inlined] owned_critical_section::lock(this=<unavailable>) at cubeb_utils_unix.h:56:5 [opt]
    frame #4: 0x0000000119ff152d XUL`audiounit_stream_stop(cubeb_stream*) [inlined] std::__1::lock_guard<owned_critical_section>::lock_guard(this=<unavailable>, __m=<unavailable>) at __mutex_base:104 [opt]
    frame #5: 0x0000000119ff152d XUL`audiounit_stream_stop(cubeb_stream*) [inlined] std::__1::lock_guard<owned_critical_section>::lock_guard(this=<unavailable>, __m=<unavailable>) at __mutex_base:104 [opt]
    frame #6: 0x0000000119ff152d XUL`audiounit_stream_stop(stm=0x0000000108354c00) at cubeb_audiounit.cpp:2957 [opt]
    frame #7: 0x00000001187af7bd XUL`mozilla::AudioCallbackDriver::Stop(this=0x000000018a0f1600) at GraphDriver.cpp:740:7 [opt]
    frame #8: 0x00000001187aea8b XUL`mozilla::AsyncCubebTask::Run(this=0x000000010bd14c80) at GraphDriver.cpp:462:16 [opt]
    frame #9: 0x00000001157c15bc XUL`nsThreadPool::Run(this=<unavailable>) at nsThreadPool.cpp:244:14 [opt]
    frame #10: 0x00000001157c197d XUL`non-virtual thunk to nsThreadPool::Run(this=<unavailable>) at nsThreadPool.cpp:0 [opt]
    frame #11: 0x00000001157ba9fc XUL`nsThread::ProcessNextEvent(this=0x000000010bc772f0, aMayWait=<unavailable>, aResult=0x000070000a59edef) at nsThread.cpp:1225:14 [opt]
    frame #12: 0x00000001157be928 XUL`NS_ProcessNextEvent(aThread=<unavailable>, aMayWait=<unavailable>) at nsThreadUtils.cpp:486:10 [opt]
    frame #13: 0x0000000115ef6ccd XUL`mozilla::ipc::MessagePumpForNonMainThreads::Run(this=0x000000010bd46ac0, aDelegate=0x000000018fecef40) at MessagePump.cpp:333:5 [opt]
    frame #14: 0x0000000115e88ef5 XUL`MessageLoop::Run() [inlined] MessageLoop::RunHandler(this=<unavailable>) at message_loop.cc:308:3 [opt]
    frame #15: 0x0000000115e88ef0 XUL`MessageLoop::Run(this=<unavailable>) at message_loop.cc:290 [opt]
    frame #16: 0x00000001157b6f14 XUL`nsThread::ThreadFunc(aArg=<unavailable>) at nsThread.cpp:458:11 [opt]
    frame #17: 0x0000000107e24ff0 libnss3.dylib`_pt_root(arg=0x000000018d8262f0) at ptthread.c:198:5 [opt]
    frame #18: 0x00007fff72a662eb libsystem_pthread.dylib`_pthread_body + 126
    frame #19: 0x00007fff72a69249 libsystem_pthread.dylib`_pthread_start + 66
    frame #20: 0x00007fff72a6540d libsystem_pthread.dylib`thread_start + 13

Can you try using the reinit_pending flag [1] in audiounit_output_callback to exit callback without stopping anything? We can do the same thing we do in shutdown [2].

[1] https://searchfox.org/mozilla-central/source/media/libcubeb/src/cubeb_audiounit.cpp#239
[2] https://searchfox.org/mozilla-central/rev/9775cca0a10a9b5c5f4e15c8f7b3eff5bf91bbd0/media/libcubeb/src/cubeb_audiounit.cpp#608-612

The reason why Rust backend works is that the stream shutdown is called before output drains hence the output callback doesn’t try to get the CAMutex (it only happens when draining). As a result, the deadlock between output callback and the internal callback of the hardware device change inside the CoreAudio won’t be formed.

The following are the code sequences I observed:

C backend

  1. reinit: start then pending on trying to get a CAMutex to stop AudioUnits, holding the mutex for Cubeb context
  2. output callback: device switching, feed silence
  3. ....
  4. output callback: device switching, feed silence
  5. stream stop: start then pending on trying to get the mutex for Cubeb context
  6. output callback: drains and pending on trying to get a CAMutex

Rust backend

  1. reinit: start then pending on trying to get a CAMutex to stop AudioUnits
  2. output callback: device switching, feed silence
  3. ....
  4. output callback: device switching, feed silence
  5. stream stop: start and ask stream to shut down, pending on trying to get CAMutex to stop the audio units
  6. output callback: output shutdown, feed silence
  7. …..
  8. output callback: output shutdown, feed silence
  9. reinit: get the CAMutex and stop AudioUnits, start reinitializing the stream
  10. stream stop: Get the CAMutex and stop AudioUnits again.
  11. reinit: finish reinit stuff

(BTW, I smell a potential problem: during reinit, we will stop the stream to do some reinit settings. If the stream starts is called in the middle of the stream reinitialization, we might have a racing issue. However, I don't think this exists in gecko.)

(In reply to Alex Chronopoulos [:achronop] from comment #3)

It is strange that we get a reinit and a drain at the same time.

It looks like the draining is intended.

(In reply to Alex Chronopoulos [:achronop] from comment #7)

Can you try using the reinit_pending flag [1] in audiounit_output_callback to exit callback without stopping anything?

That works. Then we don't need to get the CAMutex when the device changing is working. I'll submit a pull-request in the cubeb repo later.

We can do the same thing we do in shutdown [2].

I think we can leave the code as it is since we don't try getting another mutex when the stream is shutting down.

Do you think you can create a patch on cubeb repo? I can review it.

(In reply to Alex Chronopoulos [:achronop] from comment #11)

Do you think you can create a patch on cubeb repo? I can review it.

Thanks! here is the pull request: https://github.com/kinetiknz/cubeb/pull/528
try result is here: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8b2368127419bb229a9a42fd07fb2883ca4a580f

(In reply to C.M.Chang[:chunmin] from comment #8)

The reason why Rust backend works is that the stream shutdown is called before output drains hence the output callback doesn’t try to get the CAMutex (it only happens when draining). As a result, the deadlock between output callback and the internal callback of the hardware device change inside the CoreAudio won’t be formed.

Technically, in the Rust backend, the deadlock might be formed. The GraphDriver will initiate a stream stop/shutdown task and then set the stream to drain in an output callback when it detects the device switching. Then, if the next output callback comes before the stream stop/shutdown task, the next output callback will try requiring the CAMutex for the input AudioUnit and then forms a deadlock. However, I cannot produce this on my MacBook.

Here is the code sequence when I do the STR:

  1. reinit: start then pending on trying to get a CAMutex to stop AudioUnits
  2. output callback: device switching, feed silence to the input buffer
  3. ....
  4. output callback: device switching, feed silence to the input buffer and set stream to drain
  5. stream stop: start and ask stream to shut down, pending on trying to get CAMutex to stop the audio units
  6. output callback: output shutdown, feed silence to the output buffer
  7. …..
  8. output callback: output shutdown, feed silence to the output buffer
  9. reinit: get the CAMutex and stop AudioUnits, start reinitializing the stream
  10. stream stop: Get the CAMutex and stop AudioUnits again.
  11. reinit: finish reinit stuff

To be specific, if the output callback thread at 6 above comes before the the stream stop thread at 5 above, then the deadlock might be formed.

The cubeb stream shutdown task will be initiated before the stream is set to drain in the output callback, but technically it doesn't guarantee the shutdown task runs before the next output callback.

However, in my MacBook, the stream stop/shutdown always comes before the stream is drained.

(In reply to C.M.Chang[:chunmin] from comment #13)

Technically, in the Rust backend, the deadlock might be formed. The GraphDriver will initiat a stream stop/shutdown task and then set the stream to drain in a output callback when it detects the device switching. Then, if the next output callback comes before the stream stop/shutdown task, the next output callback will try requiring the CAMutex for the input AudioUnit and then forms a deadlock. However, I cannot produce this on my MacBook.

This can be proven by changing some code. With the STR, the deadlock can be produced by either commenting the setting of shutdown or returning an error directly when stream stop is called. The thread stacks (by lldb) are pretty similar.

See Also: → 1574632
Attached file GitHub Pull Request —

cubeb #528 is imported by bug 1603384. I am going to mark this resolved.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: