1743610 - Main thread hang in audioipc_server_new_client when opening new window

Status: RESOLVED DUPLICATE of bug 1735905

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

Description

[Zdenek Kabelac]

+++ This bug was initially created as a clone of Bug #1583996 +++

No STR and so far it only happened once, but I have a core file and I've obtained stack traces; I have full debug info for libxul (it's an optimized local build) but not currently for PulseAudio. I opened a new window and the browser locked up; I found the main thread blocked waiting for a Rust future in audioipc_server_new_client. I notice there are several other threads blocked in PulseAudio-related things, but I don't know this area enough to see what the root cause might be.

+++++

So I'm likely hitting this bug again on my Fedora box with:
firefox-94.0.2-1.fc36.x86_64

An easy way to hit this issue seem to be playing with aliexpress pages.

To avoid 'self-blocking' firefox I could kill 'pulseaudio' (and having silent box) and the deadlocking of firefox upon processing some windows is gone.

I could be wrong - but it really looks like very similar issue.
Here is backtrace of firefox process when I observe deadlock:

#0 __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x7fa03c265788)
at futex-internal.c:57
#1 __futex_abstimed_wait_common
(futex_word=futex_word@entry=0x7fa03c265788, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0, cancel=cancel@entry=true) at futex-internal.c:87
#2 0x00007fa06baeb3bf in __GI___futex_abstimed_wait_cancelable64
(futex_word=futex_word@entry=0x7fa03c265788, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0) at futex-internal.c:139
#3 0x00007fa06baedb40 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x7fa03c265640, cond=0x7fa03c265760)
at pthread_cond_wait.c:503
#4 ___pthread_cond_wait (cond=0x7fa03c265760, mutex=0x7fa03c265640) at pthread_cond_wait.c:618
#5 0x00007fa06346dbc5 in futures::task_impl::std::ThreadNotify::park () at /usr/lib64/firefox/libxul.so
#6 0x00007fa0633256f8 in audioipc_server_new_client () at /usr/lib64/firefox/libxul.so
#7 0x00007fa0628f16e8 in mozilla::CubebUtils::CreateAudioIPCConnectionUnlocked() () at /usr/lib64/firefox/libxul.so
#8 0x00007fa0628f164d in mozilla::CubebUtils::CreateAudioIPCConnection() () at /usr/lib64/firefox/libxul.so
#9 0x00007fa062af23a1 in mozilla::dom::ContentParent::RecvCreateAudioIPCConnection(std::function<void (mozilla::dom::FileDescOrError const&)>&&) () at /usr/lib64/firefox/libxul.so
#10 0x00007fa061fbad26 in mozilla::dom::PContentParent::OnMessageReceived(IPC::Message const&) () at /usr/lib64/firefox/libxul.so
#11 0x00007fa061fb7a4f in mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) () at /usr/lib64/firefox/libxul.so
#12 0x00007fa061fb7731 in mozilla::ipc::MessageChannel::MessageTask::Run() () at /usr/lib64/firefox/libxul.so
#13 0x00007fa061f9c260 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) () at /usr/lib64/firefox/libxul.so
#14 0x00007fa061f9bc58 in mozilla::TaskController::ProcessPendingMTTask(bool) () at /usr/lib64/firefox/libxul.so
#15 0x00007fa0622003d6 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::{lambda()#1}>::Run() ()
at /usr/lib64/firefox/libxul.so
#16 0x00007fa061f9b027 in nsThread::ProcessNextEvent(bool, bool*) () at /usr/lib64/firefox/libxul.so
#17 0x00007fa061f9a670 in NS_ProcessNextEvent(nsIThread*, bool) () at /usr/lib64/firefox/libxul.so
#18 0x00007fa061fb752a in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) () at /usr/lib64/firefox/libxul.so
#19 0x00007fa06237c0bc in MessageLoop::Run() () at /usr/lib64/firefox/libxul.so
#20 0x00007fa062bb246d in nsBaseAppShell::Run() () at /usr/lib64/firefox/libxul.so
#21 0x00007fa062f44a46 in nsAppStartup::Run() () at /usr/lib64/firefox/libxul.so
#22 0x00007fa062f84ed1 in XREMain::XRE_mainRun() () at /usr/lib64/firefox/libxul.so
#23 0x00007fa062f82243 in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) () at /usr/lib64/firefox/libxul.so
#24 0x00007fa062f81e5e in XRE_main(int, char**, mozilla::BootstrapConfig const&) () at /usr/lib64/firefox/libxul.so
--Type <RET> for more, q to quit, c to continue without paging--
#25 0x000055cca6d4307f in do_main(int, char**, char**) (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>)
at /usr/src/debug/firefox-94.0.2-1.fc36.x86_64/browser/app/nsBrowserApp.cpp:225
#26 0x000055cca6d33fb6 in main(int, char**, char**) (argc=<optimized out>, argv=<optimized out>, envp=0x7fff512aa608)
at /usr/src/debug/firefox-94.0.2-1.fc36.x86_64/browser/app/nsBrowserApp.cpp:392

I could also note that closing Firefox takes 'ages' - and pulseaudio eats some CPU all the time (1-2% while nothing is being played).

Comment 1

[Matthew Gregan [:kinetik]]

This could be bug 1735905, if your Firefox was built with rustc 1.54 (with LLVM 12) or newer.

If you experience this hang again, backtraces of all threads in the parent and all child processes would be very useful. More specifically, I'm interested in what's happening in the parent process main thread, any "AudioIPC" threads in the parent and all child processes, any other threads calling into cubeb_* in the parent and all child processes. Thanks!

Comment 2

[Zdenek Kabelac]

Let me know If you have in mind some set of gdb commands to be executed.

Otherwise there are literary hundreds of threads and many tasks as well - I'll see what I could collect.

It's worth to note that firefox is actually not playing any sound - I just click on some knob on page and it blocks this way.

Comment 3

[Matthew Gregan [:kinetik]]

Thanks. Something like the following should work:

1. pstree -pT <PID of main Firefox process>
2. For each listed process:
   gdb -batch -ex="thread apply all bt" -p PID > firefox_PID.txt
3. Archive and attach the set of firefox_PID.txt files to the bug.

Comment 4

[Zdenek Kabelac]

Attachment: send.tgz

So here comes the requested stack trace from FF when it gets into the state of being 'blocked' & unusable for further browsing.

I'd tried likely unnecessarily hard to collect better trace - but full XUL debuginfo actually does not fit into 4G memory together with blocked FF with as low as 1 process enabled in preferences.

So the trace is missing debuginfo for this - but still should provide at least named function.

If it would be really hard to resolve the puzzle I could likely try in bigger box to reproduce eventually.

So far I've noticed this:

Thread 39 (Thread 0x7f3908246640 (LWP 65588) "AudioIPC Callba"):
#0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1 0x00007f392e68451e in epoll_wait () at /usr/lib64/firefox/libxul.so
#2 0x00007f393029cb0b in tokio_reactor::Reactor::turn () at /usr/lib64/firefox/libxul.so
#3 0x00007f392f9f1529 in tokio::runtime::current_thread::runtime::Runtime::block_on () at /usr/lib64/firefox/libxul.so
#4 0x00007f392f9f4d26 in std::sys_common::backtrace::__rust_begin_short_backtrace () at /usr/lib64/firefox/libxul.so
#5 0x00007f392f9f4ae0 in core::ops::function::FnOnce::call_once{{vtable.shim}} () at /usr/lib64/firefox/libxul.so
#6 0x00007f392fff2815 in std::sys::unix::thread::Thread::new::thread_start () at /usr/lib64/firefox/libxul.so
#7 0x00007f39381bc767 in start_thread (arg=<optimized out>) at pthread_create.c:434
#8 0x00007f3938241580 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Does it mean the 'audio' processing hit some recoverable error which it is trying to recover from ??

Anyway - not an expert - so full tgz is attached for in-depth look.

As said for me it's not hard to reproduce - just browsing aliexpress pages with checking 'orders' and trying to make it 'arrived' is usually a very quick way how to block it.

Comment 5

[Zdenek Kabelac]

(As for rust version - ATM Fedora builds FF likely with this version: rust-1.55.0-2.fc36.x86_64)

Comment 6

[Matthew Gregan [:kinetik]]

Thanks for the logs. It looks like content process 65566 is waiting for an audio stream to stop in thread 23, and waiting for another audio-related query (get_max_channel_count) on thread 1. The main process (65444) shows the PulseAudio mainloop idle (thread 77) but the AudioIPC server thread (thread 40) is waiting on a signal from the PA mainloop while handling the stream stop. Given this, I'm fairly sure this is bug 1735905.

If you'd like to try rebuilding your local build with this patch, it should solve the issue. Alternatively, this is fixed in Firefox 95 (currently beta, due to be released next week).

(In reply to Zdenek Kabelac from comment #4)

Does it mean the 'audio' processing hit some recoverable error which it is trying to recover from ??

That thread is idle -- __rust_begin_short_backtrace is a marker for generating backtraces, it's normal to see it appear in Rust stacks.

Comment 7

[Zdenek Kabelac]

Ok - so I'm playing with 95beta - and it looks I cannot 'stop' that easy way as I've been able with 94 - also the exit of firefox is much faster (with 94 it took ages to finally exit all tasks).

So likely it is duplicate 1735905.