mpd unresponsive after mpc next/prev

DocMarty84 commented 4 years ago

Bug report

Describe the bug

I'm facing a behavior similar to the one reported in https://github.com/MusicPlayerDaemon/MPD/issues/854 but with a different configuration:

Configure an SSHFS mounting point for the music
Use the alsa output plugin
Scan the folder
Add some tracks belonging to different folders
Play them randomly
Switch tracks, e.g. mpc next

After switching 2-3 times, mpd is stuck: it stops playing and doesn't respond to any command from mpc (timeout).

I tried a couple of things but so far I can't pinpoint what could be the reason:

I used rclone --vfs-cache-mode full instead of the regular SSHFS => same behavior
When I play tracks from the same folder, the issue doesn't happen (or maybe much less likely to happen?)
I used the random function of mpd or shuffled the playlist and played sequentially => same behavior
I used alsa, alsa + pulseaudio or pulseaudio only => the issue only appears when alsa is activated
I played the tracks located on a local folder instead of SSHFS => no issue

To reproduce the behavior, these 3 elements seem to be important: SSHFS, alsa output and random playback.

Expected Behavior

mpd continues working normally when the next command is sent.

Actual Behavior

mpd is unreachable.

Version

So far, I tested with the mpd version shipped by default in Ubuntu 20.04, Ubuntu 18.04, Debian 10 and Debian testing. I also compiled mpd 0.22 on Ubuntu 20.04, the same issue appears.

root@mpd:~# mpd --version
Music Player Daemon 0.22 (0.22)
Copyright 2003-2007 Warren Dukes <warren.dukes@gmail.com>
Copyright 2008-2018 Max Kellermann <max.kellermann@gmail.com>
This is free software; see the source for copying conditions.  There is NO
warranty; not even MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Database plugins:
 simple proxy upnp

Storage plugins:
 local smbclient udisks nfs curl

Neighbor plugins:
 smbclient upnp udisks

Decoders plugins:
 [mad] mp3 mp2
 [mpg123] mp3
 [vorbis] ogg oga
 [oggflac] ogg oga
 [flac] flac
 [opus] opus ogg oga
 [sndfile] wav aiff aif au snd paf iff svx sf voc w64 pvf xi htk caf sd2
 [audiofile] wav au aiff aif
 [dsdiff] dff
 [dsf] dsf
 [hybrid_dsd] m4a
 [faad] aac
 [mpcdec] mpc
 [wavpack] wv
 [modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm
 [mikmod] amf dsm far gdm imf it med mod mtm s3m stm stx ult uni xm
 [sidplay] sid mus str prg P00
 [wildmidi] mid
 [fluidsynth] mid
 [adplug] amd d00 hsc laa rad raw sa2
 [ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 adx afc aif aifc aiff al alaw amr anim apc ape asf atrac au aud avi avm2 avs bap bfi c93 cak cin cmv cpk daud dct divx dts dv dvd dxa eac3 film flac flc fli fll flx flv g726 gsm gxf iss m1v m2v m2t m2ts m4a m4b m4v mad mj2 mjpeg mjpg mka mkv mlp mm mmf mov mp+ mp1 mp2 mp3 mp4 mpc mpeg mpg mpga mpp mpu mve mvi mxf nc nsv nut nuv oga ogm ogv ogx oma ogg omg opus psp pva qcp qt r3d ra ram rl2 rm rmvb roq rpl rvc shn smk snd sol son spx str swf tak tgi tgq tgv thp ts tsp tta xa xvid uv uv2 vb vid vob voc vp6 vmd wav webm wma wmv wsaud wsvga wv wve rtp:// rtsp:// rtsps://
 [gme] ay gbs gym hes kss nsf nsfe sap spc vgm vgz
 [pcm]

Filters:
 libsamplerate soxr

Tag plugins:
 id3tag

Output plugins:
 shout null fifo sndio pipe alsa ao openal pulse jack httpd recorder

Encoder plugins:
 null vorbis opus lame twolame wave flac shine

Archive plugins:
 [bz2] bz2
 [zzip] zip
 [iso] iso

Input plugins:
 file archive alsa tidal qobuz curl ffmpeg smbclient nfs mms cdio_paranoia

Playlist plugins:
 extm3u m3u pls xspf asx rss soundcloud flac cue embcue

Protocols:
 file:// alsa:// cdda:// ftp:// ftps:// gopher:// hls+http:// hls+https:// http:// https:// mms:// mmsh:// mmst:// mmsu:// nfs:// qobuz:// rtmp:// rtmps:// rtmpt:// rtmpts:// rtp:// rtsp:// rtsps:// scp:// sftp:// smb:// srtp:// tidal://

Other features:
 avahi dbus udisks epoll icu inotify ipv6 systemd tcp un

Log

Here is the log stripped when I switch from one track to another. At the end, you can see the kill -3:

client: [1] opened from [::1]:55150
client: [1] process command "next"
playlist: play 1:"S/SSSSS/TTTTT/UUUUU.flac"
decoder_thread: probing plugin flac
decoder: audio_format=44100:16:2, seekable=true
playlist: queue song 1:"D/XXXXX/YYYYY/ZZZZZ.flac"
alsa_output: opened default type=PLUG
alsa_output: buffer: size=1881..15052 time=42653..341316
alsa_output: period: size=940..941 time=21333..21334
alsa_output: default period_time = buffer_time/4 = 341315/4 = 85328
alsa_output: format=S16_LE (Signed 16 bit Little Endian)
alsa_output: buffer_size=15052 period_size=940
output: opened "My ALSA Device" (alsa) audio_format=44100:16:2
output: opened "My Pulse Output" (pulse) audio_format=44100:16:2
client: [1] command returned 0
client: [1] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [1] process command list returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "plchanges "2""
exception: Failed to play on "My Pulse Output" (pulse): suspended
output: closed "My Pulse Output" (pulse)
client: [0] command returned 0
client: [1] closed
client: [0] process command "idle"
client: [0] command returned 1
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [2] opened from [::1]:55152
client: [2] process command "next"
playlist: play 1:"D/XXXXX/YYYYY/ZZZZZ.flac"

Thread 1 "mpd" received signal SIGQUIT, Quit.

Backtrace

After the kill -3:

(gdb) thread apply all bt

Thread 8 (Thread 0x7fffe23fc700 (LWP 2430)):
#0  0x00007ffff2ccdaff in __GI___poll (fds=0x7fffc8000bb0, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff558e1d6 in  () at /lib/x86_64-linux-gnu/libpulse.so.0
#2  0x00007ffff557f841 in pa_mainloop_poll () at /lib/x86_64-linux-gnu/libpulse.so.0
#3  0x00007ffff557fec3 in pa_mainloop_iterate () at /lib/x86_64-linux-gnu/libpulse.so.0
#4  0x00007ffff557ff70 in pa_mainloop_run () at /lib/x86_64-linux-gnu/libpulse.so.0
#5  0x00007ffff558e11d in  () at /lib/x86_64-linux-gnu/libpulse.so.0
#6  0x00007fffec21167c in  () at /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-13.99.so
#7  0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#8  0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7 (Thread 0x7fffe2bfd700 (LWP 2429)):
#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7fffcc000c58) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x7fffcc000f70, cond=0x7fffcc000c30) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x7fffcc000c30, mutex=0x7fffcc000f70) at pthread_cond_wait.c:638
#3  0x00007ffff558e87c in pa_threaded_mainloop_wait () at /lib/x86_64-linux-gnu/libpulse.so.0
#4  0x00005555556abad9 in PulseOutput::Play(void const*, unsigned long) (this=0x5555558eb700, chunk=0x7fffe342eeb8, size=328) at ../../src/output/plugins/PulseOutputPlugin.cxx:787
#5  0x000055555568a525 in FilteredAudioOutput::Play(void const*, unsigned long) (this=0x5555558ecb20, data=0x7fffe342eeb8, size=328) at ../../src/output/Filtered.cxx:177
#6  0x000055555568d0a0 in AudioOutputControl::PlayChunk(std::unique_lock<std::mutex>&) (this=0x555556a8d1f0, lock=...) at ../../src/output/Thread.cxx:267
#7  0x000055555568d2fa in AudioOutputControl::InternalPlay(std::unique_lock<std::mutex>&) (this=0x555556a8d1f0, lock=...) at ../../src/output/Thread.cxx:315
#8  0x000055555568c174 in AudioOutputControl::Task() (this=0x555556a8d1f0) at ../../src/output/Thread.cxx:513
#9  0x0000555555687543 in BindMethodDetail::BindMethodWrapperGenerator2<AudioOutputControl, true, void (AudioOutputControl::*)() noexcept, &AudioOutputControl::Task, void>::Invoke(void*) (_instance=0x555556a8d1f0) at ../../src/util/BindMethod.hxx:189
#10 0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x555556a8d2b8) at ../../src/util/BindMethod.hxx:91
#11 0x0000555555611f9a in Thread::Run() (this=0x555556a8d2b8) at ../../src/thread/Thread.cxx:63
#12 0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x555556a8d2b8) at ../../src/thread/Thread.cxx:92
#13 0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#14 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 6 (Thread 0x7fffe33fe700 (LWP 2428)):
#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x555556a8cfc8) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x555556a8d020, cond=0x555556a8cfa0) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x555556a8cfa0, mutex=0x555556a8d020) at pthread_cond_wait.c:638
#3  0x00007ffff3007e20 in std::condition_variable::wait(std::unique_lock<std::mutex>&) () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x000055555568c1bf in AudioOutputControl::Task() (this=0x555556a8cec0) at ../../src/output/Thread.cxx:520
#5  0x0000555555687543 in BindMethodDetail::BindMethodWrapperGenerator2<AudioOutputControl, true, void (AudioOutputControl::*)() noexcept, &AudioOutputControl::Task, void>::Invoke(void*) (_instance=0x555556a8cec0) at ../../src/util/BindMethod.hxx:189
#6  0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x555556a8cf88) at ../../src/util/BindMethod.hxx:91
#7  0x0000555555611f9a in Thread::Run() (this=0x555556a8cf88) at ../../src/thread/Thread.cxx:63
#8  0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x555556a8cf88) at ../../src/thread/Thread.cxx:92
#9  0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 5 (Thread 0x7fffe3fff700 (LWP 2427)):
#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7fffe888d36c) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x5555558b2170, cond=0x7fffe888d340) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x7fffe888d340, mutex=0x5555558b2170) at pthread_cond_wait.c:638
#3  0x00007ffff3007e20 in std::condition_variable::wait(std::unique_lock<std::mutex>&) () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00005555555a50af in DecoderControl::Wait(std::unique_lock<std::mutex>&) (this=0x7fffe888d310, lock=...) at ../../src/decoder/Control.hxx:213
#5  0x00005555555a77e3 in NeedChunks(DecoderControl&, std::unique_lock<std::mutex>&) (dc=..., lock=...) at ../../src/decoder/Bridge.cxx:106
#6  0x00005555555a7837 in LockNeedChunks(DecoderControl&) (dc=...) at ../../src/decoder/Bridge.cxx:115
#7  0x00005555555a797a in DecoderBridge::GetChunk() (this=0x7fffe3ffe2c0) at ../../src/decoder/Bridge.cxx:136
#8  0x00005555555a8984 in DecoderBridge::SubmitData(InputStream*, void const*, unsigned long, unsigned short) (this=0x7fffe3ffe2c0, is=0x7fffd4000e60, data=0x7fffe3ffd120, length=3632, kbit_rate=192) at ../../src/decoder/Bridge.cxx:530
#9  0x00005555556b3c96 in DecoderClient::SubmitData(InputStream&, void const*, unsigned long, unsigned short) (this=0x7fffe3ffe2c0, is=..., data=0x7fffe3ffbb50, length=9216, kbit_rate=192) at ../../src/decoder/plugins/../Client.hxx:139
#10 0x00005555556c52cf in MadDecoder::SubmitPCM(unsigned long, unsigned long) (this=0x7fffe3fec270, i=0, pcm_length=1152) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:831
#11 0x00005555556c6208 in MadDecoder::SynthAndSubmit() (this=0x7fffe3fec270) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:875
#12 0x00005555556c630a in MadDecoder::HandleCurrentFrame() (this=0x7fffe3fec270) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:903
#13 0x00005555556c65e0 in MadDecoder::Read() (this=0x7fffe3fec270) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:958
#14 0x00005555556c677a in MadDecoder::RunDecoder() (this=0x7fffe3fec270) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:986
#15 0x00005555556c5345 in mad_decode(DecoderClient&, InputStream&) (client=..., input_stream=...) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:993
#16 0x00005555555a52b8 in DecoderPlugin::StreamDecode(DecoderClient&, InputStream&) const (this=0x555555842080 <mad_decoder_plugin>, client=..., is=...) at ../../src/decoder/DecoderPlugin.hxx:203
#17 0x00005555555a3479 in decoder_stream_decode(DecoderPlugin const&, DecoderBridge&, InputStream&, std::unique_lock<std::mutex>&) (plugin=..., bridge=..., input_stream=..., lock=...) at ../../src/decoder/Thread.cxx:118
#18 0x00005555555a3d82 in TryDecoderFile(DecoderBridge&, Path, char const*, InputStream&, DecoderPlugin const&) (bridge=..., path_fs=..., suffix=0x555556ae1261 "mp3", input_stream=..., plugin=...) at ../../src/decoder/Thread.cxx:345
#19 0x00005555555a3fd9 in <lambda(const DecoderPlugin&)>::operator()(const DecoderPlugin &) const (__closure=0x7fffe3ffe120, plugin=...) at ../../src/decoder/Thread.cxx:422
#20 0x00005555555a4cb7 in decoder_plugins_try<decoder_run_file(DecoderBridge&, char const*, Path)::<lambda(const DecoderPlugin&)> >(<lambda(const DecoderPlugin&)>) (f=...) at ../../src/decoder/DecoderList.hxx:72
#21 0x00005555555a40e2 in decoder_run_file(DecoderBridge&, char const*, Path) (bridge=..., uri_utf8=0x555556ae1210 "/var/lib/mpd/music/D/XXXXX/YYYYY/ZZZZZ.mp3", path_fs=...) at ../../src/decoder/Thread.cxx:420
#22 0x00005555555a4205 in DecoderUnlockedRunUri(DecoderBridge&, char const*, Path) (bridge=..., real_uri=0x555556ae1210 "/var/lib/mpd/music/D/XXXXX/YYYYY/ZZZZZ.mp3", path_fs=...) at ../../src/decoder/Thread.cxx:440
#23 0x00005555555a44ff in decoder_run_song(DecoderControl&, DetachedSong const&, char const*, Path) (dc=..., song=..., uri=0x555556ae1210 "/var/lib/mpd/music/D/XXXXX/YYYYY/ZZZZZ.mp3", path_fs=...) at ../../src/decoder/Thread.cxx:502
#24 0x00005555555a478b in decoder_run(DecoderControl&) (dc=...) at ../../src/decoder/Thread.cxx:543
#25 0x00005555555a48f1 in DecoderControl::RunThread() (this=0x7fffe888d310) at ../../src/decoder/Thread.cxx:568
#26 0x00005555555a708a in BindMethodDetail::BindMethodWrapperGenerator2<DecoderControl, true, void (DecoderControl::*)() noexcept, &DecoderControl::RunThread, void>::Invoke(void*) (_instance=0x7fffe888d310) at ../../src/util/BindMethod.hxx:189
#27 0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x7fffe888d318) at ../../src/util/BindMethod.hxx:91
#28 0x0000555555611f9a in Thread::Run() (this=0x7fffe888d318) at ../../src/thread/Thread.cxx:63
#29 0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x7fffe888d318) at ../../src/thread/Thread.cxx:92
#30 0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#31 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 4 (Thread 0x7fffe888e700 (LWP 2426)):
#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x5555558b21c0) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x5555558b2170, cond=0x5555558b2198) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x5555558b2198, mutex=0x5555558b2170) at pthread_cond_wait.c:638
#3  0x00007ffff3007e20 in std::condition_variable::wait(std::unique_lock<std::mutex>&) () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00005555555bbc65 in PlayerControl::Wait(std::unique_lock<std::mutex>&) (this=0x5555558b2128, lock=...) at ../../src/player/Control.hxx:377
#5  0x00005555555bfbc2 in PlayerControl::WaitOutputConsumed(std::unique_lock<std::mutex>&, unsigned int) (this=0x5555558b2128, lock=..., threshold=64) at ../../src/player/Control.cxx:54
#6  0x00005555555bbd08 in PlayerControl::LockWaitOutputConsumed(unsigned int) (this=0x5555558b2128, threshold=64) at ../../src/player/Control.hxx:437
#7  0x00005555555bd392 in Player::PlayNextChunk() (this=0x7fffe888d210) at ../../src/player/Thread.cxx:836
#8  0x00005555555bdfab in Player::Run() (this=0x7fffe888d210) at ../../src/player/Thread.cxx:1077
#9  0x00005555555bb5e9 in do_play(PlayerControl&, DecoderControl&, MusicBuffer&) (pc=..., dc=..., buffer=...) at ../../src/player/Thread.cxx:1157
#10 0x00005555555bb74d in PlayerControl::RunThread() (this=0x5555558b2128) at ../../src/player/Thread.cxx:1183
#11 0x00005555555c0c27 in BindMethodDetail::BindMethodWrapperGenerator2<PlayerControl, true, void (PlayerControl::*)() noexcept, &PlayerControl::RunThread, void>::Invoke(void*) (_instance=0x5555558b2128) at ../../src/util/BindMethod.hxx:189
#12 0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x5555558b2158) at ../../src/util/BindMethod.hxx:91
#13 0x0000555555611f9a in Thread::Run() (this=0x5555558b2158) at ../../src/thread/Thread.cxx:63
#14 0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x5555558b2158) at ../../src/thread/Thread.cxx:92
#15 0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#16 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 3 (Thread 0x7fffe908f700 (LWP 2425)):
#0  0x00007ffff2cda5ce in epoll_wait (epfd=9, events=0x7fffffffdf50, maxevents=16, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x000055555560c406 in EpollFD::Wait(epoll_event*, int, int) (this=0x7fffffffdf4c, events=0x7fffffffdf50, maxevents=16, timeout=-1) at ../../src/system/EpollFD.hxx:55
#2  0x000055555560c5d5 in PollGroupEpoll::ReadEvents(PollResultEpoll&, int) (this=0x7fffffffdf4c, result=..., timeout_ms=-1) at ../../src/event/PollGroupEpoll.hxx:75
#3  0x000055555560be34 in EventLoop::Run() (this=0x7fffffffdeb8) at ../../src/event/Loop.cxx:232
#4  0x000055555560b4fc in EventThread::Run() (this=0x7fffffffdeb8) at ../../src/event/Thread.cxx:65
#5  0x00005555555b5a3b in BindMethodDetail::BindMethodWrapperGenerator2<EventThread, true, void (EventThread::*)() noexcept, &EventThread::Run, void>::Invoke(void*) (_instance=0x7fffffffdeb8) at ../../src/util/BindMethod.hxx:189
#6  0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x7fffffffe020) at ../../src/util/BindMethod.hxx:91
#7  0x0000555555611f9a in Thread::Run() (this=0x7fffffffe020) at ../../src/thread/Thread.cxx:63
#8  0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x7fffffffe020) at ../../src/thread/Thread.cxx:92
#9  0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 2 (Thread 0x7fffe9890700 (LWP 2424)):
#0  0x00007ffff2cda5ce in epoll_wait (epfd=7, events=0x7fffffffddc8, maxevents=16, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x000055555560c406 in EpollFD::Wait(epoll_event*, int, int) (this=0x7fffffffddc4, events=0x7fffffffddc8, maxevents=16, timeout=-1) at ../../src/system/EpollFD.hxx:55
#2  0x000055555560c5d5 in PollGroupEpoll::ReadEvents(PollResultEpoll&, int) (this=0x7fffffffddc4, result=..., timeout_ms=-1) at ../../src/event/PollGroupEpoll.hxx:75
#3  0x000055555560be34 in EventLoop::Run() (this=0x7fffffffdd30) at ../../src/event/Loop.cxx:232
#4  0x000055555560b4fc in EventThread::Run() (this=0x7fffffffdd30) at ../../src/event/Thread.cxx:65
#5  0x00005555555b5a3b in BindMethodDetail::BindMethodWrapperGenerator2<EventThread, true, void (EventThread::*)() noexcept, &EventThread::Run, void>::Invoke(void*) (_instance=0x7fffffffdd30) at ../../src/util/BindMethod.hxx:189
#6  0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x7fffffffde98) at ../../src/util/BindMethod.hxx:91
#7  0x0000555555611f9a in Thread::Run() (this=0x7fffffffde98) at ../../src/thread/Thread.cxx:63
#8  0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x7fffffffde98) at ../../src/thread/Thread.cxx:92
#9  0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7fffe9f0e640 (LWP 2423)):
#0  0x00007ffff2cda5ce in epoll_wait (epfd=5, events=0x7fffffffdc50, maxevents=16, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x000055555560c406 in EpollFD::Wait(epoll_event*, int, int) (this=0x7fffffffdc4c, events=0x7fffffffdc50, maxevents=16, timeout=-1) at ../../src/system/EpollFD.hxx:55
#2  0x000055555560c5d5 in PollGroupEpoll::ReadEvents(PollResultEpoll&, int) (this=0x7fffffffdc4c, result=..., timeout_ms=-1) at ../../src/event/PollGroupEpoll.hxx:75
#3  0x000055555560be34 in EventLoop::Run() (this=0x7fffffffdbb8) at ../../src/event/Loop.cxx:232
#4  0x000055555558f821 in MainConfigured(options const&, ConfigData const&) (options=..., raw_config=...) at ../../src/Main.cxx:530
#5  0x000055555558faa7 in MainOrThrow(int, char**) (argc=4, argv=0x7fffffffe4c8) at ../../src/Main.cxx:606
#6  0x000055555558fb57 in mpd_main(int, char**) (argc=4, argv=0x7fffffffe4c8) at ../../src/Main.cxx:614
#7  0x000055555558fbe7 in main(int, char**) (argc=4, argv=0x7fffffffe4c8) at ../../src/Main.cxx:628

Register dump

Only on Thread 5 since it was the one playing (if I understood correctly):

(gdb) thread apply 5 i r

Thread 5 (Thread 0x7fffe3fff700 (LWP 2427)):
rax            0xfffffffffffffe00  -512
rbx            0x0                 0
rcx            0x7ffff2dba376      140737267868534
rdx            0x0                 0
rsi            0x80                128
rdi            0x7fffe888d36c      140737094669164
rbp            0x7fffe888d340      0x7fffe888d340
rsp            0x7fffe3febe50      0x7fffe3febe50
r8             0x0                 0
r9             0x4                 4
r10            0x0                 0
r11            0x282               642
r12            0x7fffe888d364      140737094669156
r13            0x5555558b2170      93824995762544
r14            0x7fffe3febe90      140737018510992
r15            0x7fffe888d36c      140737094669164
rip            0x7ffff2dba376      0x7ffff2dba376 <__pthread_cond_wait+534>
eflags         0x282               [ SF IF ]
cs             0x33                51
ss             0x2b                43
ds             0x0                 0
es             0x0                 0
fs             0x0                 0
gs             0x0                 0

Disassembly

(gdb) thread apply 5 disassemble

Thread 5 (Thread 0x7fffe3fff700 (LWP 2427)):
Dump of assembler code for function __pthread_cond_wait:
   0x00007ffff2dba160 <+0>: endbr64 
   0x00007ffff2dba164 <+4>: push   %r15
   0x00007ffff2dba166 <+6>: push   %r14
   0x00007ffff2dba168 <+8>: push   %r13
   0x00007ffff2dba16a <+10>:    mov    %rsi,%r13
   0x00007ffff2dba16d <+13>:    push   %r12
   0x00007ffff2dba16f <+15>:    push   %rbp
   0x00007ffff2dba170 <+16>:    mov    %rdi,%rbp
   0x00007ffff2dba173 <+19>:    push   %rbx
   0x00007ffff2dba174 <+20>:    sub    $0x98,%rsp
   0x00007ffff2dba17b <+27>:    mov    %fs:0x28,%rax
   0x00007ffff2dba184 <+36>:    mov    %rax,0x88(%rsp)
   0x00007ffff2dba18c <+44>:    xor    %eax,%eax
   0x00007ffff2dba18e <+46>:    nop
   0x00007ffff2dba18f <+47>:    mov    $0x2,%ebx
   0x00007ffff2dba194 <+52>:    lock xadd %rbx,(%rdi)
   0x00007ffff2dba199 <+57>:    mov    $0x8,%r14d
   0x00007ffff2dba19f <+63>:    mov    %rbx,%rax
   0x00007ffff2dba1a2 <+66>:    mov    %ebx,%r15d
   0x00007ffff2dba1a5 <+69>:    lea    0x24(%rdi),%r12
   0x00007ffff2dba1a9 <+73>:    shr    %rax
   0x00007ffff2dba1ac <+76>:    and    $0x1,%r15d
   0x00007ffff2dba1b0 <+80>:    mov    %rax,(%rsp)
   0x00007ffff2dba1b4 <+84>:    lock xadd %r14d,(%r12)
   0x00007ffff2dba1ba <+90>:    movl   $0x81,0xc(%rsp)
   0x00007ffff2dba1c2 <+98>:    and    $0x1,%r14d
   0x00007ffff2dba1c6 <+102>:   je     0x7ffff2dba1d3 <__pthread_cond_wait+115>
   0x00007ffff2dba1c8 <+104>:   mov    %r14d,0xc(%rsp)
   0x00007ffff2dba1cd <+109>:   mov    $0x80,%r14d
   0x00007ffff2dba1d3 <+115>:   xor    %esi,%esi
   0x00007ffff2dba1d5 <+117>:   mov    %r13,%rdi
   0x00007ffff2dba1d8 <+120>:   callq  0x7ffff2db76a0 <__pthread_mutex_unlock_usercnt>
   0x00007ffff2dba1dd <+125>:   test   %eax,%eax
   0x00007ffff2dba1df <+127>:   jne    0x7ffff2dba400 <__pthread_cond_wait+672>
   0x00007ffff2dba1e5 <+133>:   mov    %r15d,%eax
   0x00007ffff2dba1e8 <+136>:   lea    0x0(,%rax,4),%r9
   0x00007ffff2dba1f0 <+144>:   mov    %rax,0x10(%rsp)
   0x00007ffff2dba1f5 <+149>:   lea    0x28(%rbp,%r9,1),%r15
   0x00007ffff2dba1fa <+154>:   mov    (%r15),%eax
   0x00007ffff2dba1fd <+157>:   test   $0x1,%al
   0x00007ffff2dba1ff <+159>:   jne    0x7ffff2dba241 <__pthread_cond_wait+225>
   0x00007ffff2dba201 <+161>:   lea    0x10(%rbp),%rcx
   0x00007ffff2dba205 <+165>:   mov    %r9,0x20(%rsp)
   0x00007ffff2dba20a <+170>:   mov    %rcx,0x18(%rsp)
   0x00007ffff2dba20f <+175>:   mov    %rbx,0x28(%rsp)
   0x00007ffff2dba214 <+180>:   mov    %r14d,%ebx
   0x00007ffff2dba217 <+183>:   test   %eax,%eax
   0x00007ffff2dba219 <+185>:   je     0x7ffff2dba2f0 <__pthread_cond_wait+400>
   0x00007ffff2dba21f <+191>:   lea    -0x2(%rax),%edx
   0x00007ffff2dba222 <+194>:   lock cmpxchg %edx,(%r15)
   0x00007ffff2dba227 <+199>:   jne    0x7ffff2dba3ae <__pthread_cond_wait+590>
   0x00007ffff2dba22d <+205>:   mov    0x8(%rbp),%rdx
   0x00007ffff2dba231 <+209>:   lea    0x8(%rbp),%rcx
   0x00007ffff2dba235 <+213>:   mov    %rdx,%rax
   0x00007ffff2dba238 <+216>:   shr    %rax
   0x00007ffff2dba23b <+219>:   cmp    %rax,(%rsp)
   0x00007ffff2dba23f <+223>:   jb     0x7ffff2dba290 <__pthread_cond_wait+304>
   0x00007ffff2dba241 <+225>:   mov    $0xfffffff8,%eax
   0x00007ffff2dba246 <+230>:   lock xadd %eax,(%r12)
   0x00007ffff2dba24c <+236>:   shr    $0x2,%eax
   0x00007ffff2dba24f <+239>:   cmp    $0x3,%eax
   0x00007ffff2dba252 <+242>:   je     0x7ffff2dba3c0 <__pthread_cond_wait+608>
   0x00007ffff2dba258 <+248>:   mov    %r13,%rdi
   0x00007ffff2dba25b <+251>:   callq  0x7ffff2db7fe0 <__pthread_mutex_cond_lock>
   0x00007ffff2dba260 <+256>:   mov    %eax,%r8d
   0x00007ffff2dba263 <+259>:   mov    0x88(%rsp),%rax
   0x00007ffff2dba26b <+267>:   xor    %fs:0x28,%rax
   0x00007ffff2dba274 <+276>:   jne    0x7ffff2dba537 <__pthread_cond_wait+983>
   0x00007ffff2dba27a <+282>:   add    $0x98,%rsp
   0x00007ffff2dba281 <+289>:   mov    %r8d,%eax
   0x00007ffff2dba284 <+292>:   pop    %rbx
   0x00007ffff2dba285 <+293>:   pop    %rbp
   0x00007ffff2dba286 <+294>:   pop    %r12
   0x00007ffff2dba288 <+296>:   pop    %r13
   0x00007ffff2dba28a <+298>:   pop    %r14
   0x00007ffff2dba28c <+300>:   pop    %r15
   0x00007ffff2dba28e <+302>:   retq   
   0x00007ffff2dba28f <+303>:   nop
   0x00007ffff2dba290 <+304>:   mov    %rdx,%rax
   0x00007ffff2dba293 <+307>:   not    %rax
   0x00007ffff2dba296 <+310>:   and    $0x1,%eax
   0x00007ffff2dba299 <+313>:   cmp    %rax,0x10(%rsp)
   0x00007ffff2dba29e <+318>:   jne    0x7ffff2dba241 <__pthread_cond_wait+225>
   0x00007ffff2dba2a0 <+320>:   mov    (%r15),%eax
   0x00007ffff2dba2a3 <+323>:   mov    (%rcx),%rsi
   0x00007ffff2dba2a6 <+326>:   cmp    %rsi,%rdx
   0x00007ffff2dba2a9 <+329>:   jne    0x7ffff2dba241 <__pthread_cond_wait+225>
   0x00007ffff2dba2ab <+331>:   test   $0x1,%al
   0x00007ffff2dba2ad <+333>:   jne    0x7ffff2dba2b9 <__pthread_cond_wait+345>
   0x00007ffff2dba2af <+335>:   lea    0x2(%rax),%esi
   0x00007ffff2dba2b2 <+338>:   lock cmpxchg %esi,(%r15)
   0x00007ffff2dba2b7 <+343>:   jne    0x7ffff2dba2a3 <__pthread_cond_wait+323>
   0x00007ffff2dba2b9 <+345>:   mov    0xc(%rsp),%esi
   0x00007ffff2dba2bd <+349>:   xor    %r10d,%r10d
   0x00007ffff2dba2c0 <+352>:   mov    $0x1,%edx
   0x00007ffff2dba2c5 <+357>:   mov    %r15,%rdi
   0x00007ffff2dba2c8 <+360>:   mov    $0xca,%eax
   0x00007ffff2dba2cd <+365>:   syscall 
   0x00007ffff2dba2cf <+367>:   cmp    $0xfffffffffffff000,%rax
   0x00007ffff2dba2d5 <+373>:   jbe    0x7ffff2dba241 <__pthread_cond_wait+225>
   0x00007ffff2dba2db <+379>:   add    $0x16,%eax
   0x00007ffff2dba2de <+382>:   and    $0xfffffff7,%eax
   0x00007ffff2dba2e1 <+385>:   jne    0x7ffff2dba3ee <__pthread_cond_wait+654>
   0x00007ffff2dba2e7 <+391>:   jmpq   0x7ffff2dba241 <__pthread_cond_wait+225>
   0x00007ffff2dba2ec <+396>:   nopl   0x0(%rax)
   0x00007ffff2dba2f0 <+400>:   mov    0x18(%rsp),%rax
   0x00007ffff2dba2f5 <+405>:   add    0x20(%rsp),%rax
   0x00007ffff2dba2fa <+410>:   mov    %rax,0x30(%rsp)
   0x00007ffff2dba2ff <+415>:   lock addl $0x2,(%rax)
   0x00007ffff2dba303 <+419>:   mov    (%r15),%eax
   0x00007ffff2dba306 <+422>:   test   $0x1,%al
   0x00007ffff2dba308 <+424>:   jne    0x7ffff2dba4f0 <__pthread_cond_wait+912>
   0x00007ffff2dba30e <+430>:   mov    0x8(%rbp),%rax
   0x00007ffff2dba312 <+434>:   shr    %rax
   0x00007ffff2dba315 <+437>:   cmp    %rax,(%rsp)
   0x00007ffff2dba319 <+441>:   jb     0x7ffff2dba4f0 <__pthread_cond_wait+912>
   0x00007ffff2dba31f <+447>:   mov    0x28(%rsp),%rax
   0x00007ffff2dba324 <+452>:   movq   %r13,%xmm1
   0x00007ffff2dba329 <+457>:   movq   %rbp,%xmm0
   0x00007ffff2dba32e <+462>:   lea    0x40(%rsp),%r14
   0x00007ffff2dba333 <+467>:   punpcklqdq %xmm1,%xmm0
   0x00007ffff2dba337 <+471>:   lea    0x60(%rsp),%rdx
   0x00007ffff2dba33c <+476>:   mov    %r14,%rdi
   0x00007ffff2dba33f <+479>:   mov    %ebx,0x78(%rsp)
   0x00007ffff2dba343 <+483>:   lea    -0x2fa(%rip),%rsi        # 0x7ffff2dba050 <__condvar_cleanup_waiting>
   0x00007ffff2dba34a <+490>:   mov    %rax,0x60(%rsp)
   0x00007ffff2dba34f <+495>:   movups %xmm0,0x68(%rsp)
   0x00007ffff2dba354 <+500>:   callq  0x7ffff2dbdbf0 <_pthread_cleanup_push>
   0x00007ffff2dba359 <+505>:   callq  0x7ffff2dbdfe0 <__pthread_enable_asynccancel>
   0x00007ffff2dba35e <+510>:   mov    %ebx,%esi
   0x00007ffff2dba360 <+512>:   xor    %r10d,%r10d
   0x00007ffff2dba363 <+515>:   xor    %edx,%edx
   0x00007ffff2dba365 <+517>:   mov    %eax,%r8d
   0x00007ffff2dba368 <+520>:   xor    $0x80,%sil
   0x00007ffff2dba36c <+524>:   mov    %r15,%rdi
   0x00007ffff2dba36f <+527>:   mov    $0xca,%eax
   0x00007ffff2dba374 <+532>:   syscall 
=> 0x00007ffff2dba376 <+534>:   cmp    $0xfffffffffffff000,%rax
   0x00007ffff2dba37c <+540>:   ja     0x7ffff2dba4a8 <__pthread_cond_wait+840>
   0x00007ffff2dba382 <+546>:   mov    %r8d,%edi
   0x00007ffff2dba385 <+549>:   callq  0x7ffff2dbe040 <__pthread_disable_asynccancel>
   0x00007ffff2dba38a <+554>:   xor    %esi,%esi
   0x00007ffff2dba38c <+556>:   mov    %r14,%rdi
   0x00007ffff2dba38f <+559>:   callq  0x7ffff2dbdc20 <_pthread_cleanup_pop>
   0x00007ffff2dba394 <+564>:   mov    0x30(%rsp),%rcx
   0x00007ffff2dba399 <+569>:   mov    $0xfffffffe,%eax
   0x00007ffff2dba39e <+574>:   lock xadd %eax,(%rcx)
   0x00007ffff2dba3a2 <+578>:   cmp    $0x3,%eax
   0x00007ffff2dba3a5 <+581>:   je     0x7ffff2dba468 <__pthread_cond_wait+776>
   0x00007ffff2dba3ab <+587>:   mov    (%r15),%eax
   0x00007ffff2dba3ae <+590>:   test   $0x1,%al
   0x00007ffff2dba3b0 <+592>:   je     0x7ffff2dba217 <__pthread_cond_wait+183>
   0x00007ffff2dba3b6 <+598>:   jmpq   0x7ffff2dba241 <__pthread_cond_wait+225>
   0x00007ffff2dba3bb <+603>:   nopl   0x0(%rax,%rax,1)
   0x00007ffff2dba3c0 <+608>:   mov    0xc(%rsp),%esi
   0x00007ffff2dba3c4 <+612>:   xor    %r10d,%r10d
   0x00007ffff2dba3c7 <+615>:   mov    $0x7fffffff,%edx
   0x00007ffff2dba3cc <+620>:   mov    %r12,%rdi
   0x00007ffff2dba3cf <+623>:   mov    $0xca,%eax
   0x00007ffff2dba3d4 <+628>:   syscall 
   0x00007ffff2dba3d6 <+630>:   cmp    $0xfffffffffffff000,%rax
   0x00007ffff2dba3dc <+636>:   jbe    0x7ffff2dba258 <__pthread_cond_wait+248>
   0x00007ffff2dba3e2 <+642>:   add    $0x16,%eax
   0x00007ffff2dba3e5 <+645>:   and    $0xfffffff7,%eax
   0x00007ffff2dba3e8 <+648>:   je     0x7ffff2dba258 <__pthread_cond_wait+248>
   0x00007ffff2dba3ee <+654>:   lea    0x7c0b(%rip),%rdi        # 0x7ffff2dc2000
   0x00007ffff2dba3f5 <+661>:   callq  0x7ffff2db1630 <__libc_fatal@plt>
   0x00007ffff2dba3fa <+666>:   nopw   0x0(%rax,%rax,1)
   0x00007ffff2dba400 <+672>:   mov    (%rsp),%rsi
   0x00007ffff2dba404 <+676>:   mov    %r14d,%ecx
   0x00007ffff2dba407 <+679>:   mov    %r15d,%edx
   0x00007ffff2dba40a <+682>:   mov    %rbp,%rdi
   0x00007ffff2dba40d <+685>:   mov    %eax,0x10(%rsp)
   0x00007ffff2dba411 <+689>:   callq  0x7ffff2db9e60 <__condvar_cancel_waiting>
   0x00007ffff2dba416 <+694>:   mov    $0xfffffff8,%eax
   0x00007ffff2dba41b <+699>:   lock xadd %eax,(%r12)
   0x00007ffff2dba421 <+705>:   mov    0x10(%rsp),%r8d
   0x00007ffff2dba426 <+710>:   shr    $0x2,%eax
   0x00007ffff2dba429 <+713>:   cmp    $0x3,%eax
   0x00007ffff2dba42c <+716>:   jne    0x7ffff2dba263 <__pthread_cond_wait+259>
   0x00007ffff2dba432 <+722>:   mov    0xc(%rsp),%esi
   0x00007ffff2dba436 <+726>:   xor    %r10d,%r10d
   0x00007ffff2dba439 <+729>:   mov    $0x7fffffff,%edx
   0x00007ffff2dba43e <+734>:   mov    %r12,%rdi
   0x00007ffff2dba441 <+737>:   mov    $0xca,%eax
   0x00007ffff2dba446 <+742>:   syscall 
   0x00007ffff2dba448 <+744>:   cmp    $0xfffffffffffff000,%rax
   0x00007ffff2dba44e <+750>:   jbe    0x7ffff2dba263 <__pthread_cond_wait+259>
   0x00007ffff2dba454 <+756>:   add    $0x16,%eax
   0x00007ffff2dba457 <+759>:   and    $0xfffffff7,%eax
   0x00007ffff2dba45a <+762>:   jne    0x7ffff2dba3ee <__pthread_cond_wait+654>
   0x00007ffff2dba45c <+764>:   jmpq   0x7ffff2dba263 <__pthread_cond_wait+259>
   0x00007ffff2dba461 <+769>:   nopl   0x0(%rax)
   0x00007ffff2dba468 <+776>:   mov    0x30(%rsp),%rax
   0x00007ffff2dba46d <+781>:   lock andl $0xfffffffe,(%rax)
   0x00007ffff2dba471 <+785>:   xor    %r10d,%r10d
   0x00007ffff2dba474 <+788>:   mov    $0x7fffffff,%edx
   0x00007ffff2dba479 <+793>:   mov    0xc(%rsp),%esi
   0x00007ffff2dba47d <+797>:   mov    %rax,%rdi
   0x00007ffff2dba480 <+800>:   mov    $0xca,%eax
   0x00007ffff2dba485 <+805>:   syscall 
   0x00007ffff2dba487 <+807>:   cmp    $0xfffffffffffff000,%rax
   0x00007ffff2dba48d <+813>:   jbe    0x7ffff2dba3ab <__pthread_cond_wait+587>
   0x00007ffff2dba493 <+819>:   add    $0x16,%eax
   0x00007ffff2dba496 <+822>:   and    $0xfffffff7,%eax
   0x00007ffff2dba499 <+825>:   jne    0x7ffff2dba3ee <__pthread_cond_wait+654>
   0x00007ffff2dba49f <+831>:   jmpq   0x7ffff2dba3ab <__pthread_cond_wait+587>
   0x00007ffff2dba4a4 <+836>:   nopl   0x0(%rax)
   0x00007ffff2dba4a8 <+840>:   mov    %r8d,%edi
   0x00007ffff2dba4ab <+843>:   mov    %rax,0x38(%rsp)
   0x00007ffff2dba4b0 <+848>:   callq  0x7ffff2dbe040 <__pthread_disable_asynccancel>
   0x00007ffff2dba4b5 <+853>:   mov    0x38(%rsp),%rax
   0x00007ffff2dba4ba <+858>:   lea    0xb(%rax),%ecx
   0x00007ffff2dba4bd <+861>:   cmp    $0xb,%ecx
   0x00007ffff2dba4c0 <+864>:   ja     0x7ffff2dba3ee <__pthread_cond_wait+654>
   0x00007ffff2dba4c6 <+870>:   mov    $0x1,%edx
   0x00007ffff2dba4cb <+875>:   shl    %cl,%rdx
   0x00007ffff2dba4ce <+878>:   test   $0x881,%edx
   0x00007ffff2dba4d4 <+884>:   je     0x7ffff2dba3ee <__pthread_cond_wait+654>
   0x00007ffff2dba4da <+890>:   xor    %esi,%esi
   0x00007ffff2dba4dc <+892>:   mov    %r14,%rdi
   0x00007ffff2dba4df <+895>:   callq  0x7ffff2dbdc20 <_pthread_cleanup_pop>
   0x00007ffff2dba4e4 <+900>:   jmpq   0x7ffff2dba394 <__pthread_cond_wait+564>
   0x00007ffff2dba4e9 <+905>:   nopl   0x0(%rax)
   0x00007ffff2dba4f0 <+912>:   mov    0x30(%rsp),%rcx
   0x00007ffff2dba4f5 <+917>:   mov    $0xfffffffe,%eax
   0x00007ffff2dba4fa <+922>:   lock xadd %eax,(%rcx)
   0x00007ffff2dba4fe <+926>:   cmp    $0x3,%eax
   0x00007ffff2dba501 <+929>:   jne    0x7ffff2dba241 <__pthread_cond_wait+225>
   0x00007ffff2dba507 <+935>:   mov    0x30(%rsp),%rax
   0x00007ffff2dba50c <+940>:   lock andl $0xfffffffe,(%rax)
   0x00007ffff2dba510 <+944>:   xor    %r10d,%r10d
   0x00007ffff2dba513 <+947>:   mov    $0x7fffffff,%edx
   0x00007ffff2dba518 <+952>:   mov    0xc(%rsp),%esi
   0x00007ffff2dba51c <+956>:   mov    %rax,%rdi
   0x00007ffff2dba51f <+959>:   mov    $0xca,%eax
   0x00007ffff2dba524 <+964>:   syscall 
   0x00007ffff2dba526 <+966>:   cmp    $0xfffffffffffff000,%rax
   0x00007ffff2dba52c <+972>:   jbe    0x7ffff2dba241 <__pthread_cond_wait+225>
   0x00007ffff2dba532 <+978>:   jmpq   0x7ffff2dba2db <__pthread_cond_wait+379>
   0x00007ffff2dba537 <+983>:   callq  0x7ffff2db16d0 <__stack_chk_fail@plt>
End of assembler dump.

Let me know if there is any other useful information I can provide. If necessary, I can make a VM available.

Thanks

MaxKellermann commented 4 years ago

Your log shows that there were problems with PulseAudio and that the Pulseaudio output has been closed, but your backtrace shows that PulseAudio is open and MPD is waiting for PulseAudio. That's not consistent. Your backtrace also shows that the MPD main thread is not blocked - it is ready and waiting to receive commands from clients. That's not consistent with the whole bug description. Something is very wrong with the data you posted, it doesn't make sense. Maybe try disabling PulseAudio completely, to avoid this problem. Then, to break in gdb, don't use SIGQUIT but SIGTRAP. SIGQUIT tells MPD to shut down, and SIGTRAP is used to break into a debugger.

MaxKellermann commented 4 years ago

Also, your log doesn't show any "mpc next" command.

DocMarty84 commented 4 years ago

Thanks for the reply, here is the extra information you requested.

There are 4 tracks which didn't cause any issue: ZZZZZZZZZZ, AAAAAAAAAA, BBBBBBBBBB and CCCCCCCCCC. Finally, mpd timed-out at track DDDDDDDDDD. You will note that DDDDDDDDDD is in the log, but the backtrace mentions CCCCCCCCCC. I guess it correlates the fact that DDDDDDDDDD never started playing.

Let me know if there is something else I can provide.

Configuration

PulseAudio is not enabled:

root@mpd:~# egrep -v '^#' /etc/mpd.conf | egrep -v '^$'
music_directory     "/var/lib/mpd/music"
playlist_directory      "/var/lib/mpd/playlists"
db_file         "/var/lib/mpd/tag_cache"
log_file            "/var/log/mpd/mpd.log"
pid_file            "/run/mpd/pid"
state_file          "/var/lib/mpd/state"
sticker_file                   "/var/lib/mpd/sticker.sql"
user                "mpd"
bind_to_address     "localhost"
input {
        plugin "curl"
}
input {
        enabled    "no"
        plugin     "qobuz"
}
input {
        enabled      "no"
        plugin       "tidal"
}
decoder {
        plugin                  "hybrid_dsd"
        enabled                 "no"
}
audio_output {
    type        "alsa"
    name        "My ALSA Device"
}
filesystem_charset      "UTF-8"

mpc commands

Here is the list of mpc commands sent until timeout:

root@mpd:~# mpc
ZZZZZZZZZZ
[playing] #1/450   0:11/2:14 (8%)
volume:100%   repeat: off   random: off   single: off   consume: on 
root@mpd:~# mpc next
AAAAAAAAAA
[playing] #1/449   0:00/4:50 (0%)
volume:100%   repeat: off   random: off   single: off   consume: on 
root@mpd:~# mpc next
BBBBBBBBBB
[playing] #1/448   0:00/0:35 (0%)
volume:100%   repeat: off   random: off   single: off   consume: on 
root@mpd:~# mpc next
CCCCCCCCCC
[playing] #1/447   0:00/4:18 (0%)
volume:100%   repeat: off   random: off   single: off   consume: on 
root@mpd:~# mpc next
MPD error: Timeout
root@mpd:~# kill -s SIGTRAP `pgrep mpd`

Log

Here is the complete log from program start to SIGTRAP:

Starting program: /usr/local/bin/mpd -v --stdout --no-daemon /etc/mpd.conf
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
config_file: loading file /etc/mpd.conf
path: SetFSCharset: fs charset is:
libsamplerate: libsamplerate converter 'Fastest Sinc Interpolator'
vorbis: Xiph.Org libVorbis 1.3.6
opus: libopus 1.3.1
sndfile: libsndfile-1.0.28
exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
adplug: adplug 2.3.1
simple_db: reading DB
curl: version 7.68.0
curl: with GnuTLS/3.6.13
[New Thread 0x7fffe9890700 (LWP 1200)]
[New Thread 0x7fffe908f700 (LWP 1201)]
avahi: Initializing interface
exception: RTIOThread could not get realtime scheduling, continuing anyway: sched_setscheduler failed: Operation not permitted
avahi: Client changed to state 2
avahi: Client is RUNNING
avahi: Registering service _mpd._tcp/Music Player @ mpd
avahi: Service group changed to state 0
avahi: Service group is UNCOMMITED
state_file: Loading state file /var/lib/mpd/state
[New Thread 0x7fffe888e700 (LWP 1202)]
[New Thread 0x7fffe3fff700 (LWP 1203)]
playlist: queue song 1:"AAAAAAAAAA.flac"
[New Thread 0x7fffe33fe700 (LWP 1204)]
exception: OutputThread could not get realtime scheduling, continuing anyway: sched_setscheduler failed: Operation not permitted
avahi: Service group changed to state 1
avahi: Service group is REGISTERING
decoder_thread: probing plugin flac
decoder: audio_format=44100:16:2, seekable=true
alsa_output: opened default type=PLUG
alsa_output: buffer: size=1881..15052 time=42653..341316
alsa_output: period: size=940..941 time=21333..21334
alsa_output: default period_time = buffer_time/4 = 341315/4 = 85328
alsa_output: format=S16_LE (Signed 16 bit Little Endian)
alsa_output: buffer_size=15052 period_size=940
output: opened "My ALSA Device" (alsa) audio_format=44100:16:2
avahi: Service group changed to state 2
avahi: Service 'Music Player @ mpd' successfully established.
client: [0] opened from [::1]:55922
client: [0] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [0] process command list returned 0
client: [0] closed
client: [1] opened from [::1]:55924
client: [1] process command "next"
playlist: play 1:"AAAAAAAAAA.flac"
decoder_thread: probing plugin flac
decoder: audio_format=44100:16:2, seekable=true
playlist: queue song 1:"BBBBBBBBBB.flac"
client: [1] command returned 0
client: [1] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [1] process command list returned 0
client: [1] closed
client: [2] opened from [::1]:55926
client: [2] process command "next"
playlist: play 1:"BBBBBBBBBB.flac"
decoder_thread: probing plugin flac
decoder: audio_format=44100:16:2, seekable=true
playlist: queue song 1:"CCCCCCCCCC.mp3"
client: [2] command returned 0
client: [2] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [2] process command list returned 0
client: [2] closed
client: [3] opened from [::1]:55928
client: [3] process command "next"
playlist: play 1:"CCCCCCCCCC.mp3"
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=true
playlist: queue song 1:"DDDDDDDDDD.flac"
alsa_output: opened default type=PLUG
alsa_output: buffer: size=1881..15052 time=42653..341316
alsa_output: period: size=940..941 time=21333..21334
alsa_output: default period_time = buffer_time/4 = 341315/4 = 85328
alsa_output: format=S24_LE (Signed 24 bit Little Endian)
alsa_output: buffer_size=15052 period_size=940
output: opened "My ALSA Device" (alsa) audio_format=44100:24:2
client: [3] command returned 0
client: [3] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [3] process command list returned 0
client: [3] closed
client: [4] opened from [::1]:55930
client: [4] process command "next"
playlist: play 1:"DDDDDDDDDD.flac"

Thread 1 "mpd" received signal SIGTRAP, Trace/breakpoint trap.

Backtrace

(gdb) thread apply all bt

Thread 6 (Thread 0x7fffe33fe700 (LWP 1204)):
#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x555556a8c4f0) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x555556a8c4a0, cond=0x555556a8c4c8) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x555556a8c4c8, mutex=0x555556a8c4a0) at pthread_cond_wait.c:638
#3  0x00007ffff3007e20 in std::condition_variable::wait(std::unique_lock<std::mutex>&) () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x000055555569c344 in AlsaOutput::LockWaitWriteAvailable() (this=0x555556a8c1a0) at ../../src/output/plugins/AlsaOutputPlugin.cxx:981
#5  0x000055555569c3c2 in AlsaOutput::Play(void const*, unsigned long) (this=0x555556a8c1a0, chunk=0x7fffe3435350, size=3248) at ../../src/output/plugins/AlsaOutputPlugin.cxx:991
#6  0x000055555568a525 in FilteredAudioOutput::Play(void const*, unsigned long) (this=0x5555558eb710, data=0x7fffe3435350, size=3248) at ../../src/output/Filtered.cxx:177
#7  0x000055555568d0a0 in AudioOutputControl::PlayChunk(std::unique_lock<std::mutex>&) (this=0x555556a8c510, lock=...) at ../../src/output/Thread.cxx:267
#8  0x000055555568d2fa in AudioOutputControl::InternalPlay(std::unique_lock<std::mutex>&) (this=0x555556a8c510, lock=...) at ../../src/output/Thread.cxx:315
#9  0x000055555568c174 in AudioOutputControl::Task() (this=0x555556a8c510) at ../../src/output/Thread.cxx:513
#10 0x0000555555687543 in BindMethodDetail::BindMethodWrapperGenerator2<AudioOutputControl, true, void (AudioOutputControl::*)() noexcept, &AudioOutputControl::Task, void>::Invoke(void*) (_instance=0x555556a8c510) at ../../src/util/BindMethod.hxx:189
#11 0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x555556a8c5d8) at ../../src/util/BindMethod.hxx:91
#12 0x0000555555611f9a in Thread::Run() (this=0x555556a8c5d8) at ../../src/thread/Thread.cxx:63
#13 0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x555556a8c5d8) at ../../src/thread/Thread.cxx:92
#14 0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#15 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 5 (Thread 0x7fffe3fff700 (LWP 1203)):
#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7fffe888d36c) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x5555558b2090, cond=0x7fffe888d340) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x7fffe888d340, mutex=0x5555558b2090) at pthread_cond_wait.c:638
#3  0x00007ffff3007e20 in std::condition_variable::wait(std::unique_lock<std::mutex>&) () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00005555555a50af in DecoderControl::Wait(std::unique_lock<std::mutex>&) (this=0x7fffe888d310, lock=...) at ../../src/decoder/Control.hxx:213
#5  0x00005555555a77e3 in NeedChunks(DecoderControl&, std::unique_lock<std::mutex>&) (dc=..., lock=...) at ../../src/decoder/Bridge.cxx:106
#6  0x00005555555a7837 in LockNeedChunks(DecoderControl&) (dc=...) at ../../src/decoder/Bridge.cxx:115
#7  0x00005555555a797a in DecoderBridge::GetChunk() (this=0x7fffe3ffe2c0) at ../../src/decoder/Bridge.cxx:136
#8  0x00005555555a8984 in DecoderBridge::SubmitData(InputStream*, void const*, unsigned long, unsigned short) (this=0x7fffe3ffe2c0, is=0x7fffd4000b60, data=0x7fffe3ffcb80, length=5072, kbit_rate=192) at ../../src/decoder/Bridge.cxx:530
#9  0x00005555556b3c96 in DecoderClient::SubmitData(InputStream&, void const*, unsigned long, unsigned short) (this=0x7fffe3ffe2c0, is=..., data=0x7fffe3ffbb50, length=9216, kbit_rate=192) at ../../src/decoder/plugins/../Client.hxx:139
#10 0x00005555556c52cf in MadDecoder::SubmitPCM(unsigned long, unsigned long) (this=0x7fffe3fec270, i=0, pcm_length=1152) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:831
#11 0x00005555556c6208 in MadDecoder::SynthAndSubmit() (this=0x7fffe3fec270) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:875
#12 0x00005555556c630a in MadDecoder::HandleCurrentFrame() (this=0x7fffe3fec270) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:903
#13 0x00005555556c65e0 in MadDecoder::Read() (this=0x7fffe3fec270) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:958
#14 0x00005555556c677a in MadDecoder::RunDecoder() (this=0x7fffe3fec270) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:986
#15 0x00005555556c5345 in mad_decode(DecoderClient&, InputStream&) (client=..., input_stream=...) at ../../src/decoder/plugins/MadDecoderPlugin.cxx:993
#16 0x00005555555a52b8 in DecoderPlugin::StreamDecode(DecoderClient&, InputStream&) const (this=0x555555842080 <mad_decoder_plugin>, client=..., is=...) at ../../src/decoder/DecoderPlugin.hxx:203
#17 0x00005555555a3479 in decoder_stream_decode(DecoderPlugin const&, DecoderBridge&, InputStream&, std::unique_lock<std::mutex>&) (plugin=..., bridge=..., input_stream=..., lock=...) at ../../src/decoder/Thread.cxx:118
#18 0x00005555555a3d82 in TryDecoderFile(DecoderBridge&, Path, char const*, InputStream&, DecoderPlugin const&) (bridge=..., path_fs=..., suffix=0x555556a9dc5c "mp3", input_stream=..., plugin=...) at ../../src/decoder/Thread.cxx:345
#19 0x00005555555a3fd9 in <lambda(const DecoderPlugin&)>::operator()(const DecoderPlugin &) const (__closure=0x7fffe3ffe120, plugin=...) at ../../src/decoder/Thread.cxx:422
#20 0x00005555555a4cb7 in decoder_plugins_try<decoder_run_file(DecoderBridge&, char const*, Path)::<lambda(const DecoderPlugin&)> >(<lambda(const DecoderPlugin&)>) (f=...) at ../../src/decoder/DecoderList.hxx:72
#21 0x00005555555a40e2 in decoder_run_file(DecoderBridge&, char const*, Path) (bridge=..., uri_utf8=0x555556a9dc10 "/var/lib/mpd/music/CCCCCCCCCC.mp3", path_fs=...) at ../../src/decoder/Thread.cxx:420
#22 0x00005555555a4205 in DecoderUnlockedRunUri(DecoderBridge&, char const*, Path) (bridge=..., real_uri=0x555556a9dc10 "/var/lib/mpd/music/CCCCCCCCCC.mp3", path_fs=...) at ../../src/decoder/Thread.cxx:440
#23 0x00005555555a44ff in decoder_run_song(DecoderControl&, DetachedSong const&, char const*, Path) (dc=..., song=..., uri=0x555556a9dc10 "/var/lib/mpd/music/CCCCCCCCCC.mp3", path_fs=...) at ../../src/decoder/Thread.cxx:502
#24 0x00005555555a478b in decoder_run(DecoderControl&) (dc=...) at ../../src/decoder/Thread.cxx:543
#25 0x00005555555a48f1 in DecoderControl::RunThread() (this=0x7fffe888d310) at ../../src/decoder/Thread.cxx:568
#26 0x00005555555a708a in BindMethodDetail::BindMethodWrapperGenerator2<DecoderControl, true, void (DecoderControl::*)() noexcept, &DecoderControl::RunThread, void>::Invoke(void*) (_instance=0x7fffe888d310) at ../../src/util/BindMethod.hxx:189
#27 0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x7fffe888d318) at ../../src/util/BindMethod.hxx:91
#28 0x0000555555611f9a in Thread::Run() (this=0x7fffe888d318) at ../../src/thread/Thread.cxx:63
#29 0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x7fffe888d318) at ../../src/thread/Thread.cxx:92
#30 0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#31 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 4 (Thread 0x7fffe888e700 (LWP 1202)):
#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x555556a8c648) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x555556a8c670, cond=0x555556a8c620) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x555556a8c620, mutex=0x555556a8c670) at pthread_cond_wait.c:638
#3  0x00007ffff3007e20 in std::condition_variable::wait(std::unique_lock<std::mutex>&) () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x0000555555686eb6 in std::condition_variable::wait<AudioOutputControl::WaitForCommand(std::unique_lock<std::mutex>&)::<lambda()> >(std::unique_lock<std::mutex> &, AudioOutputControl::<lambda()>) (this=0x555556a8c620, __lock=..., __p=...) at /usr/include/c++/9/condition_variable:101
#5  0x0000555555686404 in AudioOutputControl::WaitForCommand(std::unique_lock<std::mutex>&) (this=0x555556a8c510, lock=...) at ../../src/output/Control.cxx:159
#6  0x0000555555683d30 in AudioOutputControl::LockWaitForCommand() (this=0x555556a8c510) at ../../src/output/Control.hxx:335
#7  0x0000555555682902 in MultipleOutputs::WaitAll() (this=0x5555558b2000) at ../../src/output/MultipleOutputs.cxx:158
#8  0x00005555556834cb in MultipleOutputs::Cancel() (this=0x5555558b2000) at ../../src/output/MultipleOutputs.cxx:337
#9  0x00005555555bca32 in Player::SeekDecoder(std::unique_lock<std::mutex>&) (this=0x7fffe888d210, lock=...) at ../../src/player/Thread.cxx:626
#10 0x00005555555bce67 in Player::ProcessCommand(std::unique_lock<std::mutex>&) (this=0x7fffe888d210, lock=...) at ../../src/player/Thread.cxx:750
#11 0x00005555555bdcb1 in Player::Run() (this=0x7fffe888d210) at ../../src/player/Thread.cxx:1005
#12 0x00005555555bb5e9 in do_play(PlayerControl&, DecoderControl&, MusicBuffer&) (pc=..., dc=..., buffer=...) at ../../src/player/Thread.cxx:1157
#13 0x00005555555bb74d in PlayerControl::RunThread() (this=0x5555558b2048) at ../../src/player/Thread.cxx:1183
#14 0x00005555555c0c27 in BindMethodDetail::BindMethodWrapperGenerator2<PlayerControl, true, void (PlayerControl::*)() noexcept, &PlayerControl::RunThread, void>::Invoke(void*) (_instance=0x5555558b2048) at ../../src/util/BindMethod.hxx:189
#15 0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x5555558b2078) at ../../src/util/BindMethod.hxx:91
#16 0x0000555555611f9a in Thread::Run() (this=0x5555558b2078) at ../../src/thread/Thread.cxx:63
#17 0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x5555558b2078) at ../../src/thread/Thread.cxx:92
#18 0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#19 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 3 (Thread 0x7fffe908f700 (LWP 1201)):
#0  0x00007ffff2cda5ce in epoll_wait (epfd=8, events=0x7fffffffdf40, maxevents=16, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x000055555560c406 in EpollFD::Wait(epoll_event*, int, int) (this=0x7fffffffdf3c, events=0x7fffffffdf40, maxevents=16, timeout=-1) at ../../src/system/EpollFD.hxx:55
#2  0x000055555560c5d5 in PollGroupEpoll::ReadEvents(PollResultEpoll&, int) (this=0x7fffffffdf3c, result=..., timeout_ms=-1) at ../../src/event/PollGroupEpoll.hxx:75
#3  0x000055555560be34 in EventLoop::Run() (this=0x7fffffffdea8) at ../../src/event/Loop.cxx:232
#4  0x000055555560b4fc in EventThread::Run() (this=0x7fffffffdea8) at ../../src/event/Thread.cxx:65
#5  0x00005555555b5a3b in BindMethodDetail::BindMethodWrapperGenerator2<EventThread, true, void (EventThread::*)() noexcept, &EventThread::Run, void>::Invoke(void*) (_instance=0x7fffffffdea8) at ../../src/util/BindMethod.hxx:189
#6  0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x7fffffffe010) at ../../src/util/BindMethod.hxx:91
#7  0x0000555555611f9a in Thread::Run() (this=0x7fffffffe010) at ../../src/thread/Thread.cxx:63
#8  0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x7fffffffe010) at ../../src/thread/Thread.cxx:92
#9  0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 2 (Thread 0x7fffe9890700 (LWP 1200)):
#0  0x00007ffff2cda5ce in epoll_wait (epfd=6, events=0x7fffffffddb8, maxevents=16, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x000055555560c406 in EpollFD::Wait(epoll_event*, int, int) (this=0x7fffffffddb4, events=0x7fffffffddb8, maxevents=16, timeout=-1) at ../../src/system/EpollFD.hxx:55
#2  0x000055555560c5d5 in PollGroupEpoll::ReadEvents(PollResultEpoll&, int) (this=0x7fffffffddb4, result=..., timeout_ms=-1) at ../../src/event/PollGroupEpoll.hxx:75
#3  0x000055555560be34 in EventLoop::Run() (this=0x7fffffffdd20) at ../../src/event/Loop.cxx:232
#4  0x000055555560b4fc in EventThread::Run() (this=0x7fffffffdd20) at ../../src/event/Thread.cxx:65
#5  0x00005555555b5a3b in BindMethodDetail::BindMethodWrapperGenerator2<EventThread, true, void (EventThread::*)() noexcept, &EventThread::Run, void>::Invoke(void*) (_instance=0x7fffffffdd20) at ../../src/util/BindMethod.hxx:189
#6  0x000055555560ce08 in BoundMethod<void () noexcept>::operator()() const (this=0x7fffffffde88) at ../../src/util/BindMethod.hxx:91
#7  0x0000555555611f9a in Thread::Run() (this=0x7fffffffde88) at ../../src/thread/Thread.cxx:63
#8  0x0000555555611f76 in Thread::ThreadProc(void*) (ctx=0x7fffffffde88) at ../../src/thread/Thread.cxx:92
#9  0x00007ffff2db3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007ffff2cda293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7fffe9f0e640 (LWP 1199)):
#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x5555558b2110) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x5555558b2090, cond=0x5555558b20e8) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x5555558b20e8, mutex=0x5555558b2090) at pthread_cond_wait.c:638
#3  0x00007ffff3007e20 in std::condition_variable::wait(std::unique_lock<std::mutex>&) () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00005555555c0906 in PlayerControl::ClientWait(std::unique_lock<std::mutex>&) (this=0x5555558b2048, lock=...) at ../../src/player/Control.hxx:400
#5  0x00005555555c0940 in PlayerControl::WaitCommandLocked(std::unique_lock<std::mutex>&) (this=0x5555558b2048, lock=...) at ../../src/player/Control.hxx:448
#6  0x00005555555c098c in PlayerControl::SynchronousCommand(std::unique_lock<std::mutex>&, PlayerCommand) (this=0x5555558b2048, lock=..., cmd=PlayerCommand::SEEK) at ../../src/player/Control.hxx:464
#7  0x00005555555c054f in PlayerControl::SeekLocked(std::unique_lock<std::mutex>&, std::unique_ptr<DetachedSong, std::default_delete<DetachedSong> >, SongTime) (this=0x5555558b2048, lock=..., song=std::unique_ptr<class DetachedSong> = {...}, t=...) at ../../src/player/Control.cxx:272
#8  0x00005555555bfc8d in PlayerControl::Play(std::unique_ptr<DetachedSong, std::default_delete<DetachedSong> >) (this=0x5555558b2048, song=std::unique_ptr<class DetachedSong> = {...}) at ../../src/player/Control.cxx:70
#9  0x00005555555c9b46 in playlist::PlayOrder(PlayerControl&, unsigned int) (this=0x5555558b1fa8, pc=..., order=1) at ../../src/queue/Playlist.cxx:185
#10 0x00005555555ca916 in playlist::PlayNext(PlayerControl&) (this=0x5555558b1fa8, pc=...) at ../../src/queue/PlaylistControl.cxx:177
#11 0x000055555559981e in Partition::PlayNext() (this=0x5555558b1ed0) at ../../src/Partition.hxx:187
#12 0x0000555555598a9f in handle_next(Client&, Request, Response&) (client=..., args=..., r=...) at ../../src/command/PlayerCommands.cxx:231
#13 0x0000555555596490 in command_process(Client&, unsigned int, char*) (client=..., num=0, line=0x555556a9e040 "next") at ../../src/command/AllCommands.cxx:426
#14 0x00005555555aed81 in Client::ProcessLine(char*) (this=0x555556a9e010, line=0x555556a9e040 "next") at ../../src/client/Process.cxx:139
#15 0x00005555555af349 in Client::OnSocketInput(void*, unsigned long) (this=0x555556a9e010, data=0x555556a9e040, length=5) at ../../src/client/Read.cxx:49
#16 0x00005555556070a7 in BufferedSocket::ResumeInput() (this=0x555556a9e010) at ../../src/event/BufferedSocket.cxx:76
#17 0x0000555555607215 in BufferedSocket::OnSocketReady(unsigned int) (this=0x555556a9e010, flags=1) at ../../src/event/BufferedSocket.cxx:113
#18 0x0000555555607aa4 in FullyBufferedSocket::OnSocketReady(unsigned int) (this=0x555556a9e010, flags=1) at ../../src/event/FullyBufferedSocket.cxx:106
#19 0x0000555555606924 in SocketMonitor::Dispatch(unsigned int) (this=0x555556a9e010, flags=1) at ../../src/event/SocketMonitor.cxx:36
#20 0x000055555560beff in EventLoop::Run() (this=0x7fffffffdba8) at ../../src/event/Loop.cxx:249
#21 0x000055555558f821 in MainConfigured(options const&, ConfigData const&) (options=..., raw_config=...) at ../../src/Main.cxx:530
#22 0x000055555558faa7 in MainOrThrow(int, char**) (argc=5, argv=0x7fffffffe4b8) at ../../src/Main.cxx:606
#23 0x000055555558fb57 in mpd_main(int, char**) (argc=5, argv=0x7fffffffe4b8) at ../../src/Main.cxx:614
#24 0x000055555558fbe7 in main(int, char**) (argc=5, argv=0x7fffffffe4b8) at ../../src/Main.cxx:628

MaxKellermann commented 4 years ago

This could be an ALSA bug. Did you configure an ALSA plugin? For example, the Bluetooth ALSA plugin is known to be buggy, and known to cause this kind of problem. Try configuring an ALSA "hw:" device, e.g. add to the audio_output section a line like:

  device "hw:0"

MaxKellermann commented 4 years ago

More interesting information could be:

ls -l /proc/$(pidof mpd)/fd
cat /proc/$(pidof mpd)/fdinfo/8
cat /proc/$(pidof mpd)/fdinfo/6
grep asound /proc/$(pidof mpd)/maps

DocMarty84 commented 4 years ago

This could be an ALSA bug. Did you configure an ALSA plugin? For example, the Bluetooth ALSA plugin is known to be buggy, and known to cause this kind of problem. Try configuring an ALSA "hw:" device, e.g. add to the audio_output section a line like:
  device "hw:0"

No, I didn't configure any ALSA plugin. All tests are performed on a default Ubuntu/Debian installation without any specific configuration. However, this remark made me realize something: all the tests are performed in a VirtualBox VM, which is also the case in #854.

I ran the same ALSA / SSHFS config outside of a VM: no freeze of mpd! My system is an Ubuntu 18.04, but I could reproduce the problem in an Ubuntu 18.04 VirtualBox VM a few days ago.

Off-topic: I ran into the same kind of freeze issue with mopidy (also tested in a VM). I am starting to think the root cause is the same in mpd and mopidy. I still need to dig more into mopidy to make sure of that, though.

Therefore, I guess there is a bug in the combination ALSA / VirtualBox. If this is correct and you don't think it is worth handling the use case in mpd, it would be nice to document it (I can suggest a PR if you want). I am probably not the only one who experiments with a software in a VM before installing in "production"; hopefully this will save some time and frustration to future users.

By the way, I tried the device "hw:0", but the same problem appeared in the VM.

Here is the information you requested, just in case:

root@mpd:~# ls -l /proc/1159/fd
total 0
lr-x------ 1 root root 64 Sep 30 22:33 0 -> /dev/null
lrwx------ 1 root root 64 Sep 30 22:33 1 -> /dev/pts/0
lrwx------ 1 root root 64 Sep 30 22:33 10 -> 'socket:[26719]'
lrwx------ 1 root root 64 Sep 30 22:33 11 -> /var/lib/mpd/sticker.sql
lrwx------ 1 root root 64 Sep 30 22:34 12 -> 'socket:[26725]'
lrwx------ 1 root root 64 Sep 30 22:34 13 -> 'socket:[26726]'
lrwx------ 1 root root 64 Sep 30 22:34 14 -> 'anon_inode:[signalfd]'
lrwx------ 1 root root 64 Sep 30 22:34 15 -> 'socket:[26727]'
lr-x------ 1 root root 64 Sep 30 22:34 16 -> /dev/snd/timer
lr-x------ 1 root root 64 Sep 30 22:34 17 -> "CCCCCCCCCC.mp3"
lrwx------ 1 root root 64 Sep 30 22:34 18 -> /dev/snd/pcmC0D0p
lrwx------ 1 root root 64 Sep 30 22:34 19 -> /dev/snd/controlC0
lrwx------ 1 root root 64 Sep 30 22:33 2 -> /dev/pts/0
lrwx------ 1 root root 64 Sep 30 22:35 20 -> 'socket:[26258]'
lrwx------ 1 root root 64 Sep 30 22:33 3 -> 'anon_inode:[eventfd]'
lrwx------ 1 root root 64 Sep 30 22:33 4 -> 'anon_inode:[eventpoll]'
lrwx------ 1 root root 64 Sep 30 22:33 5 -> 'anon_inode:[eventfd]'
lrwx------ 1 root root 64 Sep 30 22:33 6 -> 'anon_inode:[eventpoll]'
lrwx------ 1 root root 64 Sep 30 22:33 7 -> 'anon_inode:[eventfd]'
lrwx------ 1 root root 64 Sep 30 22:33 8 -> 'anon_inode:[eventpoll]'
lrwx------ 1 root root 64 Sep 30 22:33 9 -> 'socket:[26718]'
root@mpd:~# cat /proc/1159/fdinfo/8
pos:    0
flags:  02000002
mnt_id: 15
tfd:        7 events:       19 data:     7fffffffdea8  pos:0 ino:410 sdev:e
tfd:       19 events:       39 data:     7fffe4000c38  pos:0 ino:1b9 sdev:6
tfd:       16 events:       39 data:     7fffe4000de8  pos:0 ino:188 sdev:6
root@mpd:~# cat /proc/1159/fdinfo/6
pos:    0
flags:  02000002
mnt_id: 15
tfd:        5 events:       19 data:     7fffffffdd20  pos:0 ino:410 sdev:e
root@mpd:~# grep asound /proc/1159/maps
7ffff59a2000-7ffff59cc000 r--p 00000000 08:01 394531                     /usr/lib/x86_64-linux-gnu/libasound.so.2.0.0
7ffff59cc000-7ffff5a5b000 r-xp 0002a000 08:01 394531                     /usr/lib/x86_64-linux-gnu/libasound.so.2.0.0
7ffff5a5b000-7ffff5a95000 r--p 000b9000 08:01 394531                     /usr/lib/x86_64-linux-gnu/libasound.so.2.0.0
7ffff5a95000-7ffff5a9c000 r--p 000f2000 08:01 394531                     /usr/lib/x86_64-linux-gnu/libasound.so.2.0.0
7ffff5a9c000-7ffff5a9d000 rw-p 000f9000 08:01 394531                     /usr/lib/x86_64-linux-gnu/libasound.so.2.0.0
7ffff7fb4000-7ffff7fb5000 r--p 00000000 08:01 659967                     /usr/lib/x86_64-linux-gnu/alsa-lib/libasound_module_rate_speexrate.so
7ffff7fb5000-7ffff7fb8000 r-xp 00001000 08:01 659967                     /usr/lib/x86_64-linux-gnu/alsa-lib/libasound_module_rate_speexrate.so
7ffff7fb8000-7ffff7fb9000 r--p 00004000 08:01 659967                     /usr/lib/x86_64-linux-gnu/alsa-lib/libasound_module_rate_speexrate.so
7ffff7fb9000-7ffff7fba000 r--p 00004000 08:01 659967                     /usr/lib/x86_64-linux-gnu/alsa-lib/libasound_module_rate_speexrate.so
7ffff7fba000-7ffff7fbb000 rw-p 00005000 08:01 659967                     /usr/lib/x86_64-linux-gnu/alsa-lib/libasound_module_rate_speexrate.so

MaxKellermann commented 4 years ago

Everything looks normal in your latest paste. MPD is waiting for the ALSA kernel driver to report that it has played something, so MPD can continue feeding more data into the device's buffer. So I suppose this is indeed a kernel or VM related bug. But let's keep this open for now - I have an idea how to work around this, how to keep MPD responsive even when the kernel is bugged.

MaxKellermann commented 4 years ago

@DocMarty84 please test the workaround

DocMarty84 commented 4 years ago

@DocMarty84 please test the workaround

Thanks, it works great! MPD remain responsive even when playback is faulty.

macmpi commented 4 years ago

@DocMarty84 what do yo mean by faulty playback? (distorted sound, etc...?) Will close https://github.com/MusicPlayerDaemon/MPD/issues/854 as very much seems duplicate (x86 VM & alsa)

DocMarty84 commented 3 years ago

@DocMarty84 what do yo mean by faulty playback? (distorted sound, etc...?) Will close #854 as very much seems duplicate (x86 VM & alsa)

By faulty I mean it doesn't play anymore actually.

MusicPlayerDaemon / MPD