test examples - endpoints do appear, seems to connect. but audio never starts to play back

Hi there, Have been trying to investigate an issue in failure to playback audio firefox 100. The symptom is that a connection appears on the graph, and it tries to play. However the process hangs, the timer stays at 0:00. And after a while firefox stops responding and locks up.

This problem was previously here: https://bugzilla.mozilla.org/show_bug.cgi?id=1730499

And claims to have been fixed a while ago. However I myself am now on firefox 100 and the issue still persists.

So to try to debug this problem further I downloaded and build this repo here (mozilla/cubeb) from the latest git. About an hour ago.

The project builds successfully, and it generates all of the test-* executables. However unfortunately after launching such a test program (for example test_tone or test_audio)...

So it is still doing the same bug here (as in firefox browser). The connection looks to be initiated and seemingly becomes established to the pulse audio server. Which in my case is pipewire, (but this bug has also been reported on pulse audio server too). So the connection shows up on the graph in GUI (qpwgraph). So this is the point when playback is supposed to start. But that never happens.

The stdout of the test program prints a couple of line saying it has started playback. However the playback never occurs. And the test program just sits there. Here is an example:

[id:~/.builds/firefox/cubeb-build] 130 $ ./test_audio 
Running main() from gtest_main.cc
[==========] Running 3 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 3 tests from cubeb
[ RUN      ] cubeb.run_volume_test_short

^C
[id:~/.builds/firefox/cubeb-build] 130 $

Not so sure how to proceed past this point... any advice or assistance would be greatly appreciated. Since I am just a regular firefox user. And have no particular expertise in this. Am completely lost as for what to do next. Thank you.

IDK if this could be any help. But in gdb i have to ctrl+c while its running to interrupt the program. And then the backtrace shows that it's still in the cube_stream_init ?

or to be more specific: wait_until_io_stream_ready

#5  0x00007ffff79fa25c in pa_threaded_mainloop_wait () from /lib/x86_64-linux-gnu/libpulse.so.0
#6  0x0000555555562f9a in wait_until_io_stream_ready (stream=0x5555555fa220, mainloop=0x5555555f2310) at /home/id/.builds/firefox/cubeb/src/cubeb_pulse.c:439
#7  0x0000555555562fdf in wait_until_stream_ready (stm=0x5555555fa1b0) at /home/id/.builds/firefox/cubeb/src/cubeb_pulse.c:448

[id:~/.builds/firefox/cubeb-debug] $ gdb --directory ../cubeb ./test_tone
GNU gdb (Ubuntu 12.1-0ubuntu1~22.04) 12.1
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./test_tone...
(gdb) continue
The program is not being run.
(gdb) run
Starting program: /home/id/.builds/firefox/cubeb-debug/test_tone 
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Running main() from gtest_main.cc
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from cubeb
[ RUN      ] cubeb.tone
[New Thread 0x7ffff71e6640 (LWP 2418886)]
pause

halt
^C
Thread 1 "test_tone" received signal SIGINT, Interrupt.
__futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555f24bc) at ./nptl/futex-internal.c:57
57  ./nptl/futex-internal.c: No such file or directory.
(gdb) stack
Undefined command: "stack".  Try "help".
(gdb) backtrace
#0  __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555f24bc) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (cancel=true, private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x5555555f24bc) at ./nptl/futex-internal.c:87
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x5555555f24bc, expected=expected@entry=0, clockid=clockid@entry=0, 
    abstime=abstime@entry=0x0, private=private@entry=0) at ./nptl/futex-internal.c:139
#3  0x00007ffff7ab2ac1 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x5555555f2460, cond=0x5555555f2490) at ./nptl/pthread_cond_wait.c:503
#4  ___pthread_cond_wait (cond=0x5555555f2490, mutex=0x5555555f2460) at ./nptl/pthread_cond_wait.c:627
#5  0x00007ffff79fa25c in pa_threaded_mainloop_wait () from /lib/x86_64-linux-gnu/libpulse.so.0
#6  0x0000555555562f9a in wait_until_io_stream_ready (stream=0x5555555fa220, mainloop=0x5555555f2310) at /home/id/.builds/firefox/cubeb/src/cubeb_pulse.c:439
#7  0x0000555555562fdf in wait_until_stream_ready (stm=0x5555555fa1b0) at /home/id/.builds/firefox/cubeb/src/cubeb_pulse.c:448
#8  0x0000555555565644 in pulse_stream_init (context=0x5555555f21e0, stream=0x7fffffffd388, stream_name=0x5555555ab254 "Cubeb tone (mono)", input_device=0x0, 
    input_stream_params=0x0, output_device=0x0, output_stream_params=0x7fffffffd3f0, latency_frames=4096, 
    data_callback=0x55555555ccab <data_cb_tone(cubeb_stream*, void*, void const*, void*, long)>, 
    state_callback=0x55555555ce56 <state_cb_tone(cubeb_stream*, void*, cubeb_state)>, user_ptr=0x5555555f4b20)
    at /home/id/.builds/firefox/cubeb/src/cubeb_pulse.c:1013
#9  0x000055555555f7eb in cubeb_stream_init (context=0x5555555f21e0, stream=0x7fffffffd388, stream_name=0x5555555ab254 "Cubeb tone (mono)", input_device=0x0, 
    input_stream_params=0x0, output_device=0x0, output_stream_params=0x7fffffffd3f0, latency=4096, 
    data_callback=0x55555555ccab <data_cb_tone(cubeb_stream*, void*, void const*, void*, long)>, 
    state_callback=0x55555555ce56 <state_cb_tone(cubeb_stream*, void*, cubeb_state)>, user_ptr=0x5555555f4b20) at /home/id/.builds/firefox/cubeb/src/cubeb.c:377
#10 0x000055555555d24d in cubeb_tone_Test::TestBody (this=0x5555555e6fe0) at /home/id/.builds/firefox/cubeb/test/test_tone.cpp:109
#11 0x000055555559c85c in testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void> (object=0x5555555e6fe0, 
    method=&virtual testing::Test::TestBody(), location=0x5555555b074b "the test body") at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:2090
#12 0x0000555555596b01 in testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void> (object=0x5555555e6fe0, 
    method=&virtual testing::Test::TestBody(), location=0x5555555b074b "the test body") at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:2126
#13 0x0000555555580c28 in testing::Test::Run (this=0x5555555e6fe0) at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:2161
#14 0x0000555555581432 in testing::TestInfo::Run (this=0x5555555e5ed0) at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:2338
#15 0x0000555555581a09 in testing::TestCase::Run (this=0x5555555e6360) at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:2445
#16 0x0000555555587073 in testing::internal::UnitTestImpl::RunAllTests (this=0x5555555e5fb0) at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:4237
#17 0x000055555559de51 in testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool> (object=0x5555555e5fb0, 
    method=(bool (testing::internal::UnitTestImpl::*)(testing::internal::UnitTestImpl * const)) 0x555555586dda <testing::internal::UnitTestImpl::RunAllTests()>, 
    location=0x5555555b1208 "auxiliary test code (environments or event listeners)") at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:2090
#18 0x0000555555597d61 in testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool> (object=0x5555555e5fb0, 
    method=(bool (testing::internal::UnitTestImpl::*)(testing::internal::UnitTestImpl * const)) 0x555555586dda <testing::internal::UnitTestImpl::RunAllTests()>, 
    location=0x5555555b1208 "auxiliary test code (environments or event listeners)") at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:2126
#19 0x0000555555585dac in testing::UnitTest::Run (this=0x5555555d3920 <testing::UnitTest::GetInstance()::instance>)
    at /home/id/.builds/firefox/cubeb/googletest/src/gtest.cc:3871
#20 0x000055555557b152 in main (argc=1, argv=0x7fffffffd888) at /home/id/.builds/firefox/cubeb/googletest/src/gtest_main.cc:38
(gdb)

can see in vscode here the data in the request...

ksnip_20220529-113215

then it goes into the thread loop, and gets stuck in state PA_STREAM_CREATING forever...

ksnip_20220529-113427

tried pausing the debugger and manually forcing the state of that variable to be PA_STREAM_READY. but then the program says test case failed and exits -1

not really sure what to do next. as no multi threading experience here

when i manually set the sample rate to 96000 in the test example. It does not make any difference and the thread is still stuck waiting. So i think perhaps my 96khz setup is a bit of a red herring here?

is this more of a thread locking issue? (because that was indeed the problem before, on the previous firefox 92 issue fixed by alan in the rust layer, we can see in the patch fix for that)

Can see docs for it here, the thread locking / unlocking

https://freedesktop.org/software/pulseaudio/doxygen/threaded_mainloop.html

hmm :/ i'm just not sure how much further i could possibly get. at least now without some extra assistance

ok some real progress! (finally)...

this bug occurs for me in pipewire. but only when connecting the output of this node, as a new pulse audio stream... then connecting it to a jack application. which in my case is the program bitwig studio. but potentially it could occur with other jack programs

if the connection is made, then playback does not begin because:

the receiving pulse audio source never received a reply on the threaded callback to move into state READY coming from the jack application
in this case here the pulse audio source is the cubeb test_tone, but it could potentially be other pulse audio source applications, for example: chromium, or discord, etc.

however:

if i keep this hung / waiting for READY state pulse audio source connected to the jack sink
then ALSO subsequently connect it to an additional sink...
when this 2nd sink is NOT another jack application, but something else...
typically either an alsa hardware device, or
an alsa loopback device I have tried those today
but potentially perhaps also just another regular pulse audio node could also work too (not tested but in theory)

THEN the pulse source (here cubeb) WILL

start to commence playback
that playback will be received and work for the original 1st jack connection
even if you then subsequently disconnect the 2nd triggering (not jack) sink device

and playback will continue until finished. it will work for as long as that connection persists. until the next time the pulse audio based source is re-created

So this behaviour explains why:

the bug is not typically seen (by default) in pipewire
since the default setting is: node.autoconnect = true
and that then typically will automatically connect newly created nodes to the default ALSA sink device (or whatever the default device is set in pavucontrol etc.)
you have to manually set node.autoconnect = false in the pipewire settings, so as to avoid the automatic 2nd connections that would otherwise be working around the bug here

This bug report corresponds to the following 2 pipewire bug reports:

https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/2265

and

https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/2168

Not sure if it's helpful, but the official cubeb support on Linux is cubeb-pulse-rs instead of cubeb_pulse.c now.

thanks, i have since been made aware. actually it turns out this c++ version of the library is quite nice in the sense that it is very easy to fire up the debugger and observe to see what is happening. for a typical client server interaction. in part because all these calls to llibpulse is itself also C. same language so not as much layers in the way of extra translation or hiding what is underneath. quite an education.

thanks for working on these projects. my own issue was solved this morning on pipewire side. with virtual devices as a workaround. so nothing to worry about here (or in firefox or rust side either). please consider this matter closed now, but many thanks and appreciation for being able to use your library. it really helped a lot for getting to that solution

mozilla / cubeb

test examples - endpoints do appear, seems to connect. but audio never starts to play back #706