Bug#1007100: minetest: Takes a long time to start and has no audio

[Simon McVittie]

Control: reassign -1 pipewire-pulse 0.3.48-1
Control: affects -1 + minetest libopenal1

On Fri, 11 Mar 2022 at 16:03:01 +1100, Jason Bigelow wrote:
> Since the last few days, whenever I start 5.4.1+repack-2+b1 from apt, or my own
> builds of 5.5.0 or 5.6.0-dev, Minetest takes a very long time to start, and
> fails to launch with OpenAL sound support.
> 
> I suspect the issue does not actually lie directly in Minetest but some other
> package

I get this with other games, and it seems to be a regression in Pipewire's
PulseAudio-compatible audio server, pipewire-pulse, when used with OpenAL.
0.3.48-1 has the bug, 0.3.46-1 and 0.3.47-1 do not.

A simpler reproducer is to use OpenAL's openal-info tool:

    sudo apt install openal-info wireplumber pipewire-pulse
    systemctl --user restart pipewire.service pipewire-pulse.service
    openal-info

Other relevant package versions include libopenal1/1:1.19.1-2 and
libpulse0/15.0+dfsg1-4.

Expected result: information about audio devices is displayed. It should
take 1 second or less.

Actual result:

> Available playback devices:
> BDB1539 Build signature doesn't match environment
> [at this point openal-info blocks for maybe 30 seconds]
> AL lib: (EE) ALCpulsePlayback_connectStream: Stream did not get ready: Timeout
>     Built-in Audio Analog Stereo
> Available capture devices:
>     Built-in Audio Analog Stereo
>     Monitor of Built-in Audio Analog Stereo
> Default playback device: Built-in Audio Analog Stereo
> Default capture device: Built-in Audio Analog Stereo
> ALC version: 1.1
> [at this point openal-info blocks for another 30 seconds]
> AL lib: (EE) ALCpulsePlayback_connectStream: Stream did not get ready: Timeout
>
> !!! Failed to open default device !!!

Workaround: pipewire-pulse 0.3.47-1 from snapshot.debian.org does not
have this issue.

The backtrace below is from pressing Ctrl+C during the first 30 second
pause.

    smcv

(gdb) thread apply all bt

Thread 4 (Thread 0x7ffff693b640 (LWP 52477) "threaded-ml"):
#0  0x00007ffff7dbc87f in __GI___poll (fds=fds at entry=0x7ffff0000d90, nfds=nfds at entry=2, timeout=timeout at entry=30000) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff7526a02 in poll (__timeout=30000, __nfds=2, __fds=0x7ffff0000d90) at /usr/include/x86_64-linux-gnu/bits/poll2.h:47
#2  poll_func (ufds=0x7ffff0000d90, nfds=2, timeout=30000, userdata=0x555555588ba0) at ../src/pulse/thread-mainloop.c:70
#3  0x00007ffff7518449 in pa_mainloop_poll (m=m at entry=0x55555557d4b0) at ../src/pulse/mainloop.c:863
#4  0x00007ffff7518ac7 in pa_mainloop_iterate (m=m at entry=0x55555557d4b0, block=block at entry=1, retval=retval at entry=0x0) at ../src/pulse/mainloop.c:945
#5  0x00007ffff7518b70 in pa_mainloop_run (m=0x55555557d4b0, retval=retval at entry=0x0) at ../src/pulse/mainloop.c:963
#6  0x00007ffff7526ad9 in thread (userdata=0x555555588d60) at ../src/pulse/thread-mainloop.c:101
#7  0x00007ffff74c6aef in internal_thread_func (userdata=0x55555557d070) at ../src/pulsecore/thread-posix.c:81
#8  0x00007ffff7ca2d80 in start_thread (arg=0x7ffff693b640) at pthread_create.c:481
#9  0x00007ffff7dc876f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7ffff7a17740 (LWP 52471) "openal-info"):
#0  0x00007ffff7caf0fa in __futex_abstimed_wait_common64 (futex_word=futex_word at entry=0x55555557d10c, expected=expected at entry=0, clockid=clockid at entry=0, abstime=abstime at entry=0x0, private=private at entry=0, cancel=cancel at entry=true) at ../sysdeps/nptl/futex-internal.c:74
#1  0x00007ffff7caf15b in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word at entry=0x55555557d10c, expected=expected at entry=0, clockid=clockid at entry=0, abstime=abstime at entry=0x0, private=private at entry=0) at ../sysdeps/nptl/futex-internal.c:123
#2  0x00007ffff7ca8c30 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x555555588ba0, cond=0x55555557d0e0) at pthread_cond_wait.c:504
#3  __pthread_cond_wait (cond=0x55555557d0e0, mutex=0x555555588ba0) at pthread_cond_wait.c:619
#4  0x00007ffff7527168 in pa_threaded_mainloop_wait (m=0x555555588d60) at ../src/pulse/thread-mainloop.c:216
#5  0x00007ffff7ef9189 in ALCpulsePlayback_connectStream (device_name=device_name at entry=0x0, loop=loop at entry=0x555555588d60, context=context at entry=0x55555557d5b0, flags=flags at entry=(PA_STREAM_FIX_FORMAT | PA_STREAM_FIX_RATE | PA_STREAM_FIX_CHANNELS | PA_STREAM_DONT_MOVE), attr=attr at entry=0x0, spec=spec at entry=0x7fffffffdc4c, chanmap=0x0) at ./Alc/backends/pulseaudio.c:811
#6  0x00007ffff7efa15c in ALCpulsePlayback_probeDevices () at ./Alc/backends/pulseaudio.c:608
#7  0x00007ffff7efb765 in ALCpulseBackendFactory_probe (UNUSED_self=<optimized out>, outnames=0x7ffff7f8a730 <alcAllDevicesList>, type=<optimized out>) at ./Alc/backends/pulseaudio.c:1847
#8  ALCpulseBackendFactory_ALCbackendFactory_probe (obj=<optimized out>, a=<optimized out>, b=0x7ffff7f8a730 <alcAllDevicesList>) at ./Alc/backends/pulseaudio.c:1765
#9  0x00007ffff7ec7180 in ProbeDevices (list=list at entry=0x7ffff7f8a730 <alcAllDevicesList>, backendinfo=backendinfo at entry=0x7ffff7f8a750 <PlaybackBackend>, type=type at entry=ALL_DEVICE_PROBE) at ./Alc/ALc.c:1248
#10 0x00007ffff7ec82a3 in ProbeAllDevicesList () at ./Alc/ALc.c:1254
#11 alcGetString (Device=<optimized out>, Device at entry=0x0, param=param at entry=4115) at ./Alc/ALc.c:3096
#12 0x00005555555553e7 in main (argc=1, argv=0x7fffffffdf28) at ./utils/openal-info.c:392