hangout after system suspend/resume

[Dushistov]

Bug report

Describe the bug

After machine suspend/resume (for 8-12 hours)
daemon not responding any more:

$ mpc status
MPD error: Timeout

mpc and mpd are on the same machine.

Expected Behavior

It should play music after machine resume.

Actual Behavior

It hangs.

Version

c977d64

Log

I use killall -6 and thread apply all bt gives this:

Thread 6 (Thread 0x7f0ba5fab700 (LWP 3366)):
#0  0x00007f0bb1dcacf5 in pthread_cond_wait@@GLIBC_2.3.2 () at /usr/lib/libpthread.so.0
#1  0x00007f0bb0602e71 in __gthread_cond_wait (__mutex=<optimized out>, __cond=<optimized out>) at /build/gcc/src/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:865
#2  std::condition_variable::wait(std::unique_lock<std::mutex>&) (this=<optimized out>, __lock=...) at /build/gcc/src/gcc/libstdc++-v3/src/c++11/condition_variable.cc:53
#3  0x0000558e9dbb634a in AlsaOutput::LockWaitWriteAvailable() (this=0x558e9dedd3e0) at ../src/output/plugins/AlsaOutputPlugin.cxx:981
#4  0x0000558e9dbb6420 in AlsaOutput::Play(void const*, unsigned long) (this=0x558e9dedd3e0, chunk=0x7f0ba5fb37f8, size=2056) at ../src/output/plugins/AlsaOutputPlugin.cxx:991
#5  0x0000558e9dba262b in FilteredAudioOutput::Play(void const*, unsigned long) (this=0x558e9df04460, data=0x7f0ba5fb37f8, size=2056) at ../src/output/Filtered.cxx:177
#6  0x0000558e9dba5422 in AudioOutputControl::PlayChunk(std::unique_lock<std::mutex>&) (this=0x558e9dedd750, lock=...) at ../src/output/Thread.cxx:266
#7  0x0000558e9dba576d in AudioOutputControl::InternalPlay(std::unique_lock<std::mutex>&) (this=0x558e9dedd750, lock=...) at ../src/output/Thread.cxx:314
#8  0x0000558e9dba447b in AudioOutputControl::Task() (this=0x558e9dedd750) at ../src/output/Thread.cxx:512
#9  0x0000558e9db9f71f in BindMethodDetail::BindMethodWrapperGenerator2<AudioOutputControl, true, void (AudioOutputControl::*)() noexcept, &AudioOutputControl::Task, void>::Invoke(void*) (_instance=0x558e9dedd750) at ../src/util/BindMethod.hxx:189
#10 0x0000558e9db24310 in BoundMethod<void () noexcept>::operator()() const (this=0x558e9dedd818) at ../src/util/BindMethod.hxx:91
#11 0x0000558e9db29946 in Thread::Run() (this=0x558e9dedd818) at ../src/thread/Thread.cxx:63
#12 0x0000558e9db29927 in Thread::ThreadProc(void*) (ctx=0x558e9dedd818) at ../src/thread/Thread.cxx:92
#13 0x00007f0bb1dc446f in start_thread () at /usr/lib/libpthread.so.0
#14 0x00007f0bb03123d3 in clone () at /usr/lib/libc.so.6

Thread 5 (Thread 0x7f0ba6bac700 (LWP 3365)):
#0  0x00007f0bb1dcacf5 in pthread_cond_wait@@GLIBC_2.3.2 () at /usr/lib/libpthread.so.0
#1  0x00007f0bb0602e71 in __gthread_cond_wait (__mutex=<optimized out>, __cond=<optimized out>) at /build/gcc/src/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:865
#2  std::condition_variable::wait(std::unique_lock<std::mutex>&) (this=<optimized out>, __lock=...) at /build/gcc/src/gcc/libstdc++-v3/src/c++11/condition_variable.cc:53
#3  0x0000558e9dabb477 in DecoderControl::Wait(std::unique_lock<std::mutex>&) (this=0x7f0ba73ac950, lock=...) at ../src/decoder/Control.hxx:208
#4  0x0000558e9dabeff7 in NeedChunks(DecoderControl&, std::unique_lock<std::mutex>&) (dc=..., lock=...) at ../src/decoder/Bridge.cxx:99
#5  0x0000558e9dabf047 in LockNeedChunks(DecoderControl&) (dc=...) at ../src/decoder/Bridge.cxx:108
#6  0x0000558e9dabf186 in DecoderBridge::GetChunk() (this=0x7f0ba6bab910) at ../src/decoder/Bridge.cxx:129
#7  0x0000558e9dac088d in DecoderBridge::SubmitData(InputStream*, void const*, unsigned long, unsigned short) (this=0x7f0ba6bab910, is=0x7f0b9c000e30, data=0x7f0ba6ba99f8, length=7080, kbit_rate=192) at ../src/decoder/Bridge.cxx:519
#8  0x0000558e9dbcdd0a in DecoderClient::SubmitData(InputStream&, void const*, unsigned long, unsigned short) (this=0x7f0ba6bab910, is=..., data=0x7f0ba6ba91a0, length=9216, kbit_rate=192) at ../src/decoder/plugins/../Client.hxx:139
#9  0x0000558e9dbdd589 in MadDecoder::SubmitPCM(unsigned long, unsigned long) (this=0x7f0ba6b998c0, i=0, pcm_length=1152) at ../src/decoder/plugins/MadDecoderPlugin.cxx:830
#10 0x0000558e9dbde4e8 in MadDecoder::SynthAndSubmit() (this=0x7f0ba6b998c0) at ../src/decoder/plugins/MadDecoderPlugin.cxx:874
#11 0x0000558e9dbde5e6 in MadDecoder::HandleCurrentFrame() (this=0x7f0ba6b998c0) at ../src/decoder/plugins/MadDecoderPlugin.cxx:902
#12 0x0000558e9dbde8e6 in MadDecoder::Read() (this=0x7f0ba6b998c0) at ../src/decoder/plugins/MadDecoderPlugin.cxx:957
#13 0x0000558e9dbdeaab in MadDecoder::RunDecoder() (this=0x7f0ba6b998c0) at ../src/decoder/plugins/MadDecoderPlugin.cxx:985
#14 0x0000558e9dbdd5e2 in mad_decode(DecoderClient&, InputStream&) (client=..., input_stream=...) at ../src/decoder/plugins/MadDecoderPlugin.cxx:992
#15 0x0000558e9dabb68e in DecoderPlugin::StreamDecode(DecoderClient&, InputStream&) const (this=0x558e9dd7d2c0 <mad_decoder_plugin>, client=..., is=...) at ../src/decoder/DecoderPlugin.hxx:179
#16 0x0000558e9dab97d2 in decoder_stream_decode(DecoderPlugin const&, DecoderBridge&, InputStream&, std::unique_lock<std::mutex>&) (plugin=..., bridge=..., input_stream=..., lock=...) at ../src/decoder/Thread.cxx:82
#17 0x0000558e9daba236 in TryDecoderFile(DecoderBridge&, Path, char const*, InputStream&, DecoderPlugin const&) (bridge=..., path_fs=..., suffix=0x558e9df6c2e1 "mp3", input_stream=..., plugin=...) at ../src/decoder/Thread.cxx:290
#18 0x0000558e9daba479 in <lambda(const DecoderPlugin&)>::operator()(const DecoderPlugin &) const (__closure=0x7f0ba6bab770, plugin=...) at ../src/decoder/Thread.cxx:367
#19 0x0000558e9dabb0ab in decoder_plugins_try<decoder_run_file(DecoderBridge&, char const*, Path)::<lambda(const DecoderPlugin&)> >(<lambda(const DecoderPlugin&)>) (f=...) at ../src/decoder/DecoderList.hxx:72
#20 0x0000558e9daba5ad in decoder_run_file(DecoderBridge&, char const*, Path) (bridge=..., uri_utf8=0x558e9df6c280 "/home/evgeniy/music/mics/rakhmaninov_-_kontsert_dlya_fortepiano_s_orkestrom_2_op.18_(zaycev.net).mp3", path_fs=...) at ../src/decoder/Thread.cxx:365
#21 0x0000558e9daba6c0 in DecoderUnlockedRunUri(DecoderBridge&, char const*, Path) (bridge=..., real_uri=0x558e9df6c280 "/home/evgeniy/music/mics/rakhmaninov_-_kontsert_dlya_fortepiano_s_orkestrom_2_op.18_(zaycev.net).mp3", path_fs=...) at ../src/decoder/Thread.cxx:385
#22 0x0000558e9daba999 in decoder_run_song(DecoderControl&, DetachedSong const&, char const*, Path) (dc=..., song=..., uri=0x558e9df6c280 "/home/evgeniy/music/mics/rakhmaninov_-_kontsert_dlya_fortepiano_s_orkestrom_2_op.18_(zaycev.net).mp3", path_fs=...) at ../src/decoder/Thread.cxx:446
#23 0x0000558e9dabac2e in decoder_run(DecoderControl&) (dc=...) at ../src/decoder/Thread.cxx:487
#24 0x0000558e9dabadc4 in DecoderControl::RunThread() (this=0x7f0ba73ac950) at ../src/decoder/Thread.cxx:512
#25 0x0000558e9dabe920 in BindMethodDetail::BindMethodWrapperGenerator2<DecoderControl, true, void (DecoderControl::*)() noexcept, &DecoderControl::RunThread, void>::Invoke(void*) (_instance=0x7f0ba73ac950) at ../src/util/BindMethod.hxx:189
#26 0x0000558e9db24310 in BoundMethod<void () noexcept>::operator()() const (this=0x7f0ba73ac958) at ../src/util/BindMethod.hxx:91
#27 0x0000558e9db29946 in Thread::Run() (this=0x7f0ba73ac958) at ../src/thread/Thread.cxx:63
#28 0x0000558e9db29927 in Thread::ThreadProc(void*) (ctx=0x7f0ba73ac958) at ../src/thread/Thread.cxx:92
#29 0x00007f0bb1dc446f in start_thread () at /usr/lib/libpthread.so.0
#30 0x00007f0bb03123d3 in clone () at /usr/lib/libc.so.6

Thread 4 (Thread 0x7f0ba73ad700 (LWP 3364)):
#0  0x00007f0bb1dcacf5 in pthread_cond_wait@@GLIBC_2.3.2 () at /usr/lib/libpthread.so.0
#1  0x00007f0bb0602e71 in __gthread_cond_wait (__mutex=<optimized out>, __cond=<optimized out>) at /build/gcc/src/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:865
#2  std::condition_variable::wait(std::unique_lock<std::mutex>&) (this=<optimized out>, __lock=...) at /build/gcc/src/gcc/libstdc++-v3/src/c++11/condition_variable.cc:53
#3  0x0000558e9db9eff4 in std::condition_variable::wait<AudioOutputControl::WaitForCommand(std::unique_lock<std::mutex>&)::<lambda()> >(std::unique_lock<std::mutex> &, AudioOutputControl::<lambda()>) (this=0x558e9dedd868, __lock=..., __p=...) at /usr/include/c++/9.2.1/condition_variable:101
#4  0x0000558e9db9e336 in AudioOutputControl::WaitForCommand(std::unique_lock<std::mutex>&) (this=0x558e9dedd750, lock=...) at ../src/output/Control.cxx:159
#5  0x0000558e9db9bd8a in AudioOutputControl::LockWaitForCommand() (this=0x558e9dedd750) at ../src/output/Control.hxx:336
#6  0x0000558e9db9aada in MultipleOutputs::WaitAll() (this=0x558e9de78910) at ../src/output/MultipleOutputs.cxx:158
#7  0x0000558e9db9b783 in MultipleOutputs::Pause() (this=0x558e9de78910) at ../src/output/MultipleOutputs.cxx:320
#8  0x0000558e9dad54a7 in Player::ProcessCommand(std::unique_lock<std::mutex>&) (this=0x7f0ba73ac850, lock=...) at ../src/player/Thread.cxx:727
#9  0x0000558e9dad643d in Player::Run() (this=0x7f0ba73ac850) at ../src/player/Thread.cxx:989
#10 0x0000558e9dad3a5c in do_play(PlayerControl&, DecoderControl&, MusicBuffer&) (pc=..., dc=..., buffer=...) at ../src/player/Thread.cxx:1140
#11 0x0000558e9dad3bf9 in PlayerControl::RunThread() (this=0x558e9de78958) at ../src/player/Thread.cxx:1166
#12 0x0000558e9dad96c3 in BindMethodDetail::BindMethodWrapperGenerator2<PlayerControl, true, void (PlayerControl::*)() noexcept, &PlayerControl::RunThread, void>::Invoke(void*) (_instance=0x558e9de78958) at ../src/util/BindMethod.hxx:189
#13 0x0000558e9db24310 in BoundMethod<void () noexcept>::operator()() const (this=0x558e9de78988) at ../src/util/BindMethod.hxx:91
#14 0x0000558e9db29946 in Thread::Run() (this=0x558e9de78988) at ../src/thread/Thread.cxx:63
#15 0x0000558e9db29927 in Thread::ThreadProc(void*) (ctx=0x558e9de78988) at ../src/thread/Thread.cxx:92
#16 0x00007f0bb1dc446f in start_thread () at /usr/lib/libpthread.so.0
#17 0x00007f0bb03123d3 in clone () at /usr/lib/libc.so.6

Thread 3 (Thread 0x7f0ba7bae700 (LWP 3363)):
#0  0x00007f0bb031270e in epoll_wait () at /usr/lib/libc.so.6
#1  0x0000558e9db239ae in EpollFD::Wait(epoll_event*, int, int) (this=0x7ffeb1d1a114, events=0x7ffeb1d1a118, maxevents=16, timeout=-1) at ../src/system/EpollFD.hxx:54
#2  0x0000558e9db23b59 in PollGroupEpoll::ReadEvents(PollResultEpoll&, int) (this=0x7ffeb1d1a114, result=..., timeout_ms=-1) at ../src/event/PollGroupEpoll.hxx:75
#3  0x0000558e9db233d3 in EventLoop::Run() (this=0x7ffeb1d1a080) at ../src/event/Loop.cxx:198
#4  0x0000558e9db2289e in EventThread::Run() (this=0x7ffeb1d1a080) at ../src/event/Thread.cxx:65
#5  0x0000558e9dacd95b in BindMethodDetail::BindMethodWrapperGenerator2<EventThread, true, void (EventThread::*)() noexcept, &EventThread::Run, void>::Invoke(void*) (_instance=0x7ffeb1d1a080) at ../src/util/BindMethod.hxx:189
#6  0x0000558e9db24310 in BoundMethod<void () noexcept>::operator()() const (this=0x7ffeb1d1a1e8) at ../src/util/BindMethod.hxx:91
#7  0x0000558e9db29946 in Thread::Run() (this=0x7ffeb1d1a1e8) at ../src/thread/Thread.cxx:63
#8  0x0000558e9db29927 in Thread::ThreadProc(void*) (ctx=0x7ffeb1d1a1e8) at ../src/thread/Thread.cxx:92
#9  0x00007f0bb1dc446f in start_thread () at /usr/lib/libpthread.so.0
#10 0x00007f0bb03123d3 in clone () at /usr/lib/libc.so.6

Thread 2 (Thread 0x7f0ba83af700 (LWP 3362)):
#0  0x00007f0bb031270e in epoll_wait () at /usr/lib/libc.so.6
#1  0x0000558e9db239ae in EpollFD::Wait(epoll_event*, int, int) (this=0x7ffeb1d19f84, events=0x7ffeb1d19f88, maxevents=16, timeout=-1) at ../src/system/EpollFD.hxx:54
#2  0x0000558e9db23b59 in PollGroupEpoll::ReadEvents(PollResultEpoll&, int) (this=0x7ffeb1d19f84, result=..., timeout_ms=-1) at ../src/event/PollGroupEpoll.hxx:75
#3  0x0000558e9db233d3 in EventLoop::Run() (this=0x7ffeb1d19ef0) at ../src/event/Loop.cxx:198
#4  0x0000558e9db2289e in EventThread::Run() (this=0x7ffeb1d19ef0) at ../src/event/Thread.cxx:65
#5  0x0000558e9dacd95b in BindMethodDetail::BindMethodWrapperGenerator2<EventThread, true, void (EventThread::*)() noexcept, &EventThread::Run, void>::Invoke(void*) (_instance=0x7ffeb1d19ef0) at ../src/util/BindMethod.hxx:189
#6  0x0000558e9db24310 in BoundMethod<void () noexcept>::operator()() const (this=0x7ffeb1d1a058) at ../src/util/BindMethod.hxx:91
#7  0x0000558e9db29946 in Thread::Run() (this=0x7ffeb1d1a058) at ../src/thread/Thread.cxx:63
#8  0x0000558e9db29927 in Thread::ThreadProc(void*) (ctx=0x7ffeb1d1a058) at ../src/thread/Thread.cxx:92
#9  0x00007f0bb1dc446f in start_thread () at /usr/lib/libpthread.so.0
#10 0x00007f0bb03123d3 in clone () at /usr/lib/libc.so.6

Thread 1 (Thread 0x7f0ba87adac0 (LWP 3361)):
#0  0x00007f0bb1dcacf5 in pthread_cond_wait@@GLIBC_2.3.2 () at /usr/lib/libpthread.so.0
#1  0x00007f0bb0602e71 in __gthread_cond_wait (__mutex=<optimized out>, __cond=<optimized out>) at /build/gcc/src/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:865
#2  std::condition_variable::wait(std::unique_lock<std::mutex>&) (this=<optimized out>, __lock=...) at /build/gcc/src/gcc/libstdc++-v3/src/c++11/condition_variable.cc:53
#3  0x0000558e9dad93ac in PlayerControl::ClientWait(std::unique_lock<std::mutex>&) (this=0x558e9de78958, lock=...) at ../src/player/Control.hxx:401
#4  0x0000558e9dad93e2 in PlayerControl::WaitCommandLocked(std::unique_lock<std::mutex>&) (this=0x558e9de78958, lock=...) at ../src/player/Control.hxx:449
#5  0x0000558e9dad9458 in PlayerControl::SynchronousCommand(std::unique_lock<std::mutex>&, PlayerCommand) (this=0x558e9de78958, lock=..., cmd=PlayerCommand::PAUSE) at ../src/player/Control.hxx:465
#6  0x0000558e9dad86c1 in PlayerControl::PauseLocked(std::unique_lock<std::mutex>&) (this=0x558e9de78958, lock=...) at ../src/player/Control.cxx:125
#7  0x0000558e9dad87be in PlayerControl::LockSetPause(bool) (this=0x558e9de78958, pause_flag=true) at ../src/player/Control.cxx:151
#8  0x0000558e9daaef8b in handle_pause(Client&, Request, Response&) (client=..., args=..., r=...) at ../src/command/PlayerCommands.cxx:101
#9  0x0000558e9daad0a6 in command_process(Client&, unsigned int, char*) (client=..., num=0, line=0x558e9df6c400 "pause") at ../src/command/AllCommands.cxx:426
#10 0x0000558e9dac721d in Client::ProcessLine(char*) (this=0x558e9df6c3d0, line=0x558e9df6c400 "pause") at ../src/client/Process.cxx:139
#11 0x0000558e9dac787d in Client::OnSocketInput(void*, unsigned long) (this=0x558e9df6c3d0, data=0x558e9df6c400, length=10) at ../src/client/Read.cxx:49
#12 0x0000558e9db1e194 in BufferedSocket::ResumeInput() (this=0x558e9df6c3d0) at ../src/event/BufferedSocket.cxx:76
#13 0x0000558e9db1e36b in BufferedSocket::OnSocketReady(unsigned int) (this=0x558e9df6c3d0, flags=1) at ../src/event/BufferedSocket.cxx:113
#14 0x0000558e9db1ede2 in FullyBufferedSocket::OnSocketReady(unsigned int) (this=0x558e9df6c3d0, flags=1) at ../src/event/FullyBufferedSocket.cxx:105
#15 0x0000558e9db1d89a in SocketMonitor::Dispatch(unsigned int) (this=0x558e9df6c3d0, flags=1) at ../src/event/SocketMonitor.cxx:33
#16 0x0000558e9db2349e in EventLoop::Run() (this=0x7ffeb1d19d78) at ../src/event/Loop.cxx:215
#17 0x0000558e9daa6c10 in MainConfigured(options const&, ConfigData const&) (options=..., raw_config=...) at ../src/Main.cxx:532
#18 0x0000558e9daa6e6e in MainOrThrow(int, char**) (argc=2, argv=0x7ffeb1d1a698) at ../src/Main.cxx:608
#19 0x0000558e9daa6f17 in mpd_main(int, char**) (argc=2, argv=0x7ffeb1d1a698) at ../src/Main.cxx:616
#20 0x0000558e9daa6f9f in main(int, char**) (argc=2, argv=0x7ffeb1d1a698) at ../src/Main.cxx:630

[MaxKellermann]

Is this reproducible?
The backtrace shows that MPD is currently handling the "pause" command, but your bug report does not mention sending this command.
The output thread is currently waiting for libasound to complete playback of a chunk, but apparenty libasound doesn't do anything. This could be a kernel of libasound bug. If you can reproduce this, a strace of all threads would be useful (with strace options -tttT to show timings).

[Dushistov]

Is this reproducible?

Sort of. But it requires several hours to reproduce. Often it happens after several hours of suspend, but also happens if mpd has several hours of uptime.

The backtrace shows that MPD is currently handling the "pause" command

I forget to mention this. I run mpc pause before I suspended my machine.
After machine resumed work I ran mpc play but command ends with timeout,
so then I run mpc status and killall -6.

a strace of all threads would be useful

But log would be huge, because of reproduction will take several hours?

[Dushistov]

But it requires several hours to reproduce

And yes, often (and may be always) I run mpc pause, and then after some big enough time I run mpc play, but mpc play hangs, so I need kill mpd and start it again to get my music back.

[MaxKellermann]

There's a workaround for a similar ALSA bug in MPD 0.22.1 - please try it, maybe it "fixes" your problem as well (brach v0.22.x or after 0.22.1 is released).
(If it makes the problem go away, then this is not a fix - it is just making MPD more robust against possible bugs in ALSA.)

[MaxKellermann]

Closing, because I assume this has been fixed in MPD 0.22.1 recently.