mpd/mediaplayer crashes after the last track in the playlist
Description
Environment
None
Attachments
5
journal-mpd-valgrind.txt
22 Mar, 2022
dmesg.qemux86-64.txt
10 Mar, 2022
journal.qemux86-64.txt
10 Mar, 2022
dmesg.m3ulcb.txt
10 Mar, 2022
journal.m3ulcb.txt
10 Mar, 2022
Activity
Walt Miner
May 25, 2022 at 4:08 PM
Close for MM 13.0.0
Scott Murray
March 23, 2022 at 3:32 PM
Backporting https://gitlab.freedesktop.org/pipewire/pipewire/-/commit/16f63a3c seems to fix the issue in my testing, I'm going to upload doing so as a patch to Gerrit. The upstream discussion is at:
https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/2147
Scott Murray
March 22, 2022 at 9:40 PM
It's a bit painful to get things started, but valgrind does see what happen. @George Kiagiadakis any ideas on why pw_stream_destroy would blow up?:
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== Thread 7:
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== Invalid read of size 8
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== at 0x964C4A0: loop_iterate (loop.c:351)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x6A524EF: do_loop (thread-loop.c:262)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x71903DF: start_thread (pthread_create.c:477)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x7287D5B: thread_start (clone.S:78)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== Address 0xb114a58 is 40 bytes inside a block of size 104 free'd
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== at 0x484A438: free (vg_replace_malloc.c:540)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0xCEB62FF: impl_disconnect (module-protocol-native.c:939)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x69FF357: proxy_core_destroy (core.c:241)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x69FF357: proxy_core_destroy (core.c:218)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x6A41027: pw_proxy_destroy (proxy.c:256)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x69FFF4F: pw_core_disconnect (core.c:493)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x6A50E43: pw_stream_disconnect (stream.c:1926)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x6A50E43: pw_stream_disconnect (stream.c:1899)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x6A5119B: pw_stream_destroy (stream.c:1499)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x19D427: PipeWireOutput::Close() (PipeWireOutputPlugin.cxx:586)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x195A1F: FilteredAudioOutput::CloseOutput(bool) (Filtered.cxx:138)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x195B3B: FilteredAudioOutput::Close(bool) (Filtered.cxx:158)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x19813F: InternalClose (Thread.cxx:189)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x19813F: AudioOutputControl::Task() (Thread.cxx:511)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x17D3B7: operator() (BindMethod.hxx:78)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x17D3B7: Run (Thread.cxx:63)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x17D3B7: Thread::ThreadProc(void*) (Thread.cxx:92)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== Block was alloc'd at
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== at 0x484B64C: calloc (vg_replace_malloc.c:762)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x964D673: loop_add_io (loop.c:381)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0xCEB64DB: impl_connect_fd (module-protocol-native.c:909)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0xCEBA9A7: try_connect (local-socket.c:130)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x6A0001F: pw_context_connect (core.c:414)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x6A509A7: pw_stream_connect (stream.c:1802)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x1A161F: PipeWireOutput::Open(AudioFormat&) (PipeWireOutputPlugin.cxx:569)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x195D7F: FilteredAudioOutput::OpenOutputAndConvert(AudioFormat) (Filtered.cxx:90)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x197963: InternalOpen2 (Thread.cxx:65)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x197963: AudioOutputControl::InternalOpen(AudioFormat, MusicPipe const&) (Thread.cxx:153)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x197F83: AudioOutputControl::Task() (Thread.cxx:467)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x17D3B7: operator() (BindMethod.hxx:78)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x17D3B7: Run (Thread.cxx:63)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x17D3B7: Thread::ThreadProc(void*) (Thread.cxx:92)
Mar 22 20:57:03 h3ulcb valgrind[724]: ==724== by 0x71903DF: start_thread (pthread_create.c:477)I'll attach the full journal, there's more like the above from I assume more things accessing something already freed. If you take a look, note that the is with mpd 0.23.6 which contains the commit I mentioned in my first comment on this issue.
Scott Murray
March 22, 2022 at 8:25 PM
Getting a coredump requires adding fs.suid_dumpable = 2 to /etc/sysctl.conf. Unfortunately, whatever's happening seems to be blowing up the stack:
...
Core was generated by `/usr/bin/mpd --systemd'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0x0000ffff98000080 in ?? ()
[Current thread is 1 (Thread 0xffffa0a94110 (LWP 728))]
(gdb) bt
#0 0x0000ffff98000080 in ?? ()
#1 0x0000ffff98000b60 in ?? ()
Backtrace stopped: previous frame inner to this frame (corrupt stack?)
(gdb) info threads
Id Target Id Frame
* 1 Thread 0xffffa0a94110 (LWP 728) 0x0000ffff98000080 in ?? ()
2 Thread 0xffffa2e98110 (LWP 716) 0x0000ffffa5771ee4 in __GI_epoll_pwait (epfd=<optimized out>, events=events@entry=0xffffa2e976f0, maxevents=maxevents@entry=16, timeout=-1, set=set@entry=0x0)
at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42
3 Thread 0xffffa3699110 (LWP 715) 0x0000ffffa5771ee4 in __GI_epoll_pwait (epfd=<optimized out>, events=events@entry=0xffffa36986f0, maxevents=maxevents@entry=16, timeout=-1, set=set@entry=0x0)
at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42
4 Thread 0xffffa1295110 (LWP 727) futex_wait_cancelable (private=0, expected=0, futex_word=0xaaab083cfc24) at ../sysdeps/nptl/futex-internal.h:183
5 Thread 0xffffa1e96110 (LWP 726) futex_wait_cancelable (private=0, expected=0, futex_word=0xffffa26967d0) at ../sysdeps/nptl/futex-internal.h:183
6 Thread 0xffffa2697110 (LWP 725) futex_wait_cancelable (private=0, expected=0, futex_word=0xaaab083cfc54) at ../sysdeps/nptl/futex-internal.h:183
7 Thread 0xffffa37996e0 (LWP 714) futex_wait_cancelable (private=0, expected=0, futex_word=0xaaab083b9f64) at ../sysdeps/nptl/futex-internal.h:183So nothing really useful so far. I'm going to see if running under valgrind is workable next.
Scott Murray
March 22, 2022 at 7:07 PM
So far I've been unable to get one, for some reason it's not actually triggering systemd-coredump to write one, even though it's definitely segfaulting:
Mar 22 17:19:03 h3ulcb mpd[709]: player: played "A747-9EC0/Voodoo Child (Slight Return).ogg"
Mar 22 17:19:03 h3ulcb audit[709]: ANOM_ABEND auid=4294967295 uid=984 gid=984 ses=4294967295 pid=709 comm=41474C205069706557697265 exe="/usr/bin/mpd" sig=11 res=1
Mar 22 17:19:03 h3ulcb kernel: audit: type=1701 audit(1647969543.535:3): auid=4294967295 uid=984 gid=984 ses=4294967295 pid=709 comm=41474C205069706557697265 exe="/usr/bin/mpd" sig=11 res=1
Mar 22 17:19:03 h3ulcb systemd[1]: mpd.service: Main process exited, code=killed, status=11/SEGV
Mar 22 17:19:03 h3ulcb systemd[1]: mpd.service: Failed with result 'signal'.I don't see anything obvious around signal handling in the source tree that would be resulting in it not generating a coredump, and they talk about using gdb to get a backtrace from a coredump in their documentation around bug reports, so it's a bit puzzling. At the moment I'm trying a bump to mpd 0.23.6 just in case one of the other changes since 0.23.5 is somehow relevant, the next step after that will be tinkering to build it with some of their extra debug options.
Fixed
Details
Details
Assignee
Scott Murray
Scott MurrayReporter
Edi Feschiyan
Edi FeschiyanFix versions
Contract ID
Components
Priority
MajorCreated March 10, 2022 at 6:26 PM
Updated May 25, 2022 at 4:08 PM
Resolved March 24, 2022 at 5:43 PM
When the current audio track in Mediaplayer is the last one in the playlist, trying to skip to the next song causes mpd to segfault
Mar 10 14:32:58 m3ulcb mpd[600]: player: played "5db879ac-8eb9-4f52-a76d-5590b8716c96/Voodoo Child (Slight Return).ogg" Mar 10 14:32:58 m3ulcb audit[600]: ANOM_ABEND auid=4294967295 uid=984 gid=984 ses=4294967295 pid=600 comm=41474C205069706557697265 exe="/usr/bin/mpd" sig=11 res=1 Mar 10 14:32:58 m3ulcb kernel: audit: type=1701 audit(1646922778.601:4): auid=4294967295 uid=984 gid=984 ses=4294967295 pid=600 comm=41474C205069706557697265 exe="/usr/bin/mpd" sig1 Mar 10 14:32:58 m3ulcb systemd[1]: mpd.service: Main process exited, code=killed, status=11/SEGV Mar 10 14:32:58 m3ulcb systemd[1]: mpd.service: Failed with result 'signal'. Mar 10 14:33:00 m3ulcb dbus-daemon[598]: "No carrier" Mar 10 14:33:09 m3ulcb dbus-daemon[598]: MPD connection in error state!and after the crash mediaplayer cannot play other tracks locally.
testing the same scenario with qemux86-64 image on Minnowboard dmesg reports pipewire crashing before mpd like in the previous snippet
Mar 10 18:31:44 qemux86-64 mpd[360]: player: played "5db879ac-8eb9-4f52-a76d-5590b8716c96/Voodoo Child (Slight Return).ogg" Mar 10 18:31:44 qemux86-64 kernel: AGL PipeWire[372]: segfault at 7f67f4015520 ip 00007f67f4015520 sp 00007f67fe0ebbd8 error 15 Mar 10 18:31:44 qemux86-64 kernel: Code: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fc b2 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 <00> 00 00 00 00 00 00 00 21 02 00 00 00 00 00 00 f0 22 06 f4 67 7f Mar 10 18:31:44 qemux86-64 systemd[1]: mpd.service: Main process exited, code=killed, status=11/SEGV Mar 10 18:31:44 qemux86-64 systemd[1]: mpd.service: Failed with result 'signal'.dmesg and journal attached