2017-02-25 23:40 CET

View Issue Details Jump to Notes ]
IDProjectCategoryView StatusLast Update
0004088MPDAudio Output - Pulseaudiopublic2015-04-04 23:00
Reportercraig 
Assigned Tocirrus 
PrioritynormalSeveritymajorReproducibilityalways
StatusassignedResolutionopen 
PlatformRaspberry PiOSPidoraOS Version20
Product Version0.18 
Target VersionFixed in Version 
Summary0004088: MPD deadlocks when stopping streaming play via mpc
DescriptionWhen I change to the next URL in a streaming playlist or just stop play using mpc, MPD will often stop responding. I am using PulseAudio output.
Steps To ReproduceStart and then Stop Play. In testing I found that if I do this quickly enough where I start play and then stop it in 2 seconds or less I often see this hang.

Additional InformationBacktrace when hung.

(gdb) thread apply all bt

Thread 6 (Thread 0xb3fca380 (LWP 4777)):
#0 0xb5311e24 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
#1 0xb6f49d9c in Wait (timeout=-1, maxevents=16, events=0xb7651308, this=0xb76512b0) at src/system/EPollFD.hxx:52
#2 EventLoop::Run (this=0xb76512a0) at src/event/Loop.cxx:167
#3 0xb6f4a018 in Thread::ThreadProc (ctx=<optimized out>) at src/thread/Thread.cxx:104
#4 0xb5385dec in start_thread (arg=0xb3fca380) at pthread_create.c:311
#5 0xb53117a8 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:97 from /lib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 5 (Thread 0xb37ca380 (LWP 4778)):
#0 0xb538a79c in __pthread_cond_wait (cond=0xb6f611c0 <audio_output_client_notify+24>,
    mutex=0xb6f611a8 <audio_output_client_notify>) at pthread_cond_wait.c:187
#1 0xb6f05268 in wait (mutex=..., this=0xb6f611c0 <audio_output_client_notify+24>) at src/thread/PosixCond.hxx:58
#2 notify::Wait (this=0xb6f611a8 <audio_output_client_notify>) at src/notify.cxx:28
#3 0xb6f023a0 in audio_output_wait_all () at src/OutputAll.cxx:210
#4 0xb6f02b64 in audio_output_all_cancel () at src/OutputAll.cxx:519
#5 0xb6f1713c in Player::Run (this=0xb37c9c74, this@entry=0xb37c9c6c) at src/PlayerThread.cxx:943
#6 0xb6f17574 in do_play (buffer=..., dc=..., pc=...) at src/PlayerThread.cxx:1110
#7 player_task (arg=0xb765fe50) at src/PlayerThread.cxx:1132
#8 0xb6f4a018 in Thread::ThreadProc (ctx=<optimized out>) at src/thread/Thread.cxx:104
#9 0xb5385dec in start_thread (arg=0xb37ca380) at pthread_create.c:311
#10 0xb53117a8 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:97 from /lib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 4 (Thread 0xb2fca380 (LWP 4779)):
#0 0xb538a79c in __pthread_cond_wait (cond=0xb37c9cc0, mutex=0xb765fe68) at pthread_cond_wait.c:187
#1 0xb6f0c2ac in wait (mutex=..., this=0xb37c9cc0) at src/thread/PosixCond.hxx:58
#2 Wait (this=0xb37c9ca8) at src/DecoderControl.hxx:197
#3 need_chunks (dc=...) at src/DecoderInternal.cxx:48
#4 decoder_get_chunk (decoder=...) at src/DecoderInternal.cxx:75
#5 0xb6f0be78 in decoder_data (decoder=..., is=<optimized out>, data=0xb2fc8328, data@entry=0x2b11, length=4294967184,
    kbit_rate=320) at src/DecoderAPI.cxx:411
#6 0xb6f29c08 in decoder_data (kbit_rate=<optimized out>, length=<optimized out>, data=0x2b11, is=..., decoder=...)
    at src/DecoderAPI.hxx:146
#7 MadDecoder::SendPCM (this=0xb2fb82a0, this@entry=0xb2fb5e96, i=1024, pcm_length=3002840988)
    at src/decoder/MadDecoderPlugin.cxx:977
#8 0xb6f2a670 in SyncAndSend (this=0xb2fb5e96) at src/decoder/MadDecoderPlugin.cxx:1024
#9 Read (this=0xb2fb5e96) at src/decoder/MadDecoderPlugin.cxx:1055
#10 mp3_decode (decoder=..., input_stream=...) at src/decoder/MadDecoderPlugin.cxx:1147
#11 0xb6f0aba0 in StreamDecode (this=0xb6f51acc <mad_decoder_plugin>, is=..., decoder=...) at src/DecoderPlugin.hxx:131
#12 decoder_stream_decode (plugin=..., decoder=..., input_stream=...) at src/DecoderThread.cxx:131
#13 0xb6f0af9c in __call<bool, DecoderPlugin const&, 0u, 1u, 2u, 3u, 4u> (__args=<optimized out>, this=<optimized out>)
    at /usr/include/c++/4.8.2/functional:1296
0000014 operator()<const DecoderPlugin&, bool> (this=<optimized out>) at /usr/include/c++/4.8.2/functional:1355
0000015 decoder_plugins_try<std::_Bind<bool (*(std::reference_wrapper<Decoder>, std::reference_wrapper<InputStream>, char const*, std::_Placeholder<1>, std::reference_wrapper<bool>))(Decoder&, InputStream&, char const*, const DecoderPlugin&, bool&)> > (
    f=...) at src/DecoderList.hxx:69
#16 decoder_run_stream_locked (tried_r=@0xb2fc9bd0: false, uri=<optimized out>, is=..., decoder=...)
    at src/DecoderThread.cxx:220
#17 decoder_run_stream (uri=<optimized out>, decoder=...) at src/DecoderThread.cxx:259
0000018 decoder_run_song (dc=..., song=song@entry=0xb2609638, uri=<optimized out>) at src/DecoderThread.cxx:352
0000019 0xb6f0b164 in decoder_run (dc=...) at src/DecoderThread.cxx:400
0000020 decoder_task (arg=0xb37c9ca8) at src/DecoderThread.cxx:424
#21 0xb6f4a018 in Thread::ThreadProc (ctx=<optimized out>) at src/thread/Thread.cxx:104
0000022 0xb5385dec in start_thread (arg=0xb2fca380) at pthread_create.c:311
#23 0xb53117a8 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:97 from /lib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 3 (Thread 0xb21f4380 (LWP 4780)):
#0 0xb538a8c4 in __pthread_cond_wait (cond=0xb18005b0, mutex=0xb1800590) at pthread_cond_wait.c:178
#1 0xb51c92b4 in pa_cond_wait (c=<optimized out>, m=<optimized out>) at pulsecore/mutex-posix.c:141
#2 0xb6c9ae4c in pa_threaded_mainloop_wait (m=0xb18004b8) at pulse/thread-mainloop.c:210
#3 0xb6f3cff4 in pulse_output_play (ao=0xb766ff48, chunk=0xb18265e8, size=392, error=...)
    at src/output/PulseOutputPlugin.cxx:757
#4 0xb6f04564 in ao_plugin_play (ao=ao@entry=0xb766ff48, chunk=chunk@entry=0xb18265e8, size=size@entry=392, error=...)
    at src/OutputPlugin.cxx:88
#5 0xb6f03938 in ao_play_chunk (chunk=0xb225a130, ao=0xb766ff48) at src/OutputThread.cxx:453
#6 ao_play (ao=0xb766ff48) at src/OutputThread.cxx:521
#7 audio_output_task (arg=0xb766ff48) at src/OutputThread.cxx:660
#8 0xb6f4a018 in Thread::ThreadProc (ctx=<optimized out>) at src/thread/Thread.cxx:104
#9 0xb5385dec in start_thread (arg=0xb21f4380) at pthread_create.c:311
#10 0xb53117a8 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:97 from /lib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 2 (Thread 0xb17ff380 (LWP 4781)):
#0 0xb53054a0 in poll () at ../sysdeps/unix/syscall-template.S:81
#1 0xb6c9a6ec in poll (__timeout=-1, __nfds=2, __fds=0xb767c170) at /usr/include/bits/poll2.h:46
#2 poll_func (ufds=0xb767c170, nfds=2, timeout=-1, userdata=0xb1800590) at pulse/thread-mainloop.c:71
#3 0xb6c8a4c4 in pa_mainloop_poll (m=<optimized out>) at pulse/mainloop.c:849
#4 0xb6c8ac50 in pa_mainloop_iterate (m=<optimized out>, block=<optimized out>, retval=<optimized out>)
    at pulse/mainloop.c:931
#5 0xb6c8ad28 in pa_mainloop_run (m=<optimized out>, retval=<optimized out>) at pulse/mainloop.c:949
#6 0xb6c9a6a8 in thread (userdata=0xb18004b8) at pulse/thread-mainloop.c:90
#7 0xb51c9e10 in internal_thread_func (userdata=0xb1800620) at pulsecore/thread-posix.c:83
#8 0xb5385dec in start_thread (arg=0xb17ff380) at pthread_create.c:311
#9 0xb53117a8 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:97 from /lib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 1 (Thread 0xb4065000 (LWP 4776)):
#0 0xb538a79c in __pthread_cond_wait (cond=0xb765feb0, mutex=0xb765fe68) at pthread_cond_wait.c:187
#1 0xb6f178d8 in wait (mutex=..., this=0xb765feb0) at src/thread/PosixCond.hxx:58
#2 ClientWait (this=0xb765fe50) at src/PlayerControl.hxx:240
#3 WaitCommandLocked (this=<optimized out>) at src/PlayerControl.hxx:266
#4 SynchronousCommand (cmd=CLOSE_AUDIO, this=0xb765fe50) at src/PlayerControl.hxx:281
#5 LockSynchronousCommand (cmd=CLOSE_AUDIO, this=0xb765fe50, this@entry=0xb765fe68) at src/PlayerControl.hxx:293
#6 PlayerControl::Stop (this=this@entry=0xb765fe50) at src/PlayerControl.cxx:82
#7 0xb6f185e8 in playlist::Stop (this=0xb765fe14, pc=...) at src/PlaylistControl.cxx:41
#8 0xb6f07010 in Stop (this=<optimized out>) at src/Partition.hxx:117
#9 handle_stop (client=..., argc=<optimized out>, argv=<optimized out>) at src/command/PlayerCommands.cxx:82
#10 0xb6f062ec in command_process (client=..., num=num@entry=0, line=line@entry=0xb7687820 "stop")
    at src/command/AllCommands.cxx:372
#11 0xb6f11b90 in client_process_line (client=..., line=line@entry=0xb7687820 "stop") at src/ClientProcess.cxx:126
#12 0xb6f11c8c in Client::OnSocketInput (this=0xb7687808, data=0xb7687820, length=<optimized out>) at src/ClientRead.cxx:48
#13 0xb6f48760 in BufferedSocket::ResumeInput (this=this@entry=0xb7687808) at src/event/BufferedSocket.cxx:76
0000014 0xb6f48884 in BufferedSocket::OnSocketReady (this=0xb7687808, flags=<optimized out>) at src/event/BufferedSocket.cxx:118
0000015 0xb6f48528 in SocketMonitor::Dispatch (this=0xb7687808, flags=128) at src/event/SocketMonitor.cxx:42
#16 0xb6f49de8 in EventLoop::Run (this=0xb7653b18) at src/event/Loop.cxx:181
#17 0xb6f13f60 in mpd_main (argc=<optimized out>, argv=<optimized out>) at src/Main.cxx:510
0000018 0xb524a4d4 in __libc_start_main (main=0xbea0eee4, argc=-1254641664, argv=0xb524a4d4 <__libc_start_main+276>,
    init=<optimized out>, fini=0xb6f4d4a8 <__libc_csu_fini>, rtld_fini=0xb6ed53b8 <_dl_fini>, stack_end=0xbea0eee4)
    at libc-start.c:285
0000019 0xb6f020f8 in _start ()
(gdb)
TagsNo tags attached.
Attached Files

-Relationships
+Relationships

-Notes

~0008751

cirrus (administrator)

Which version exactly?

Paste verbose log.

~0008753

craig (reporter)

I am using 0.18.13.

I can use this command sequence to trigger the hang.

while true; do echo STOP; mpc stop; sleep 1; echo PLAY; mpc play; sleep 1; date; done


Here is verbose output.

[craig@pidora src]$ cat mpd.log
config_file: loading file /etc/mpd.conf
server_socket: bind to '0.0.0.0:6600' failed: Address already in use (continuing anyway, because binding to '[::]:6600' succeeded)
path: SetFSCharset: fs charset is: UTF-8
libsamplerate: libsamplerate converter 'Fastest Sinc Interpolator'
opus: libopus 1.1
db: reading DB
curl: version 7.29.0
curl: with NSS/3.15.1
soundcloud: disabling the soundcloud playlist plugin because API key is not set
avahi: Initializing interface
avahi: Client changed to state 2
avahi: Client is RUNNING
avahi: Registering service _mpd._tcp/Music Player
avahi: Service group changed to state 0
avahi: Service group is UNCOMMITED
state_file: Loading state file /var/lib/mpd/mpdstate
avahi: Service group changed to state 1
avahi: Service group is REGISTERING
avahi: Service group changed to state 2
avahi: Service 'Music Player' successfully established.
client: [0] opened from 127.0.0.1:41883
client: [0] process command "stop"
client: [0] command returned 0
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 127.0.0.1:41884
client: [1] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [1] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
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
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
output: opened plugin=pulse name="My Pulse Output" audio_format=44100:16:2
output: converting from 44100:24:2
client: [2] opened from 127.0.0.1:41886
client: [2] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
output: closed plugin=pulse name="My Pulse Output"
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 127.0.0.1:41887
client: [3] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [3] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
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
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
output: opened plugin=pulse name="My Pulse Output" audio_format=44100:16:2
output: converting from 44100:24:2
client: [4] opened from 127.0.0.1:41889
client: [4] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
output: closed plugin=pulse name="My Pulse Output"
client: [4] command returned 0
client: [4] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [4] process command list returned 0
client: [4] closed
client: [5] opened from 127.0.0.1:41890
client: [5] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [5] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
client: [5] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [5] process command list returned 0
client: [5] closed
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
output: opened plugin=pulse name="My Pulse Output" audio_format=44100:16:2
output: converting from 44100:24:2
client: [6] opened from 127.0.0.1:41892
client: [6] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
output: closed plugin=pulse name="My Pulse Output"
client: [6] command returned 0
client: [6] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [6] process command list returned 0
client: [6] closed
client: [7] opened from 127.0.0.1:41893
client: [7] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [7] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
client: [7] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [7] process command list returned 0
client: [7] closed
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
output: opened plugin=pulse name="My Pulse Output" audio_format=44100:16:2
output: converting from 44100:24:2
client: [8] opened from 127.0.0.1:41895
client: [8] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
output: closed plugin=pulse name="My Pulse Output"
client: [8] command returned 0
client: [8] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [8] process command list returned 0
client: [8] closed
client: [9] opened from 127.0.0.1:41896
client: [9] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [9] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
client: [9] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [9] process command list returned 0
client: [9] closed
client: [10] opened from 127.0.0.1:41898
client: [10] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [10] command returned 0
client: [10] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [10] process command list returned 0
client: [10] closed
client: [11] opened from 127.0.0.1:41899
client: [11] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [11] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
client: [11] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [11] process command list returned 0
client: [11] closed
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
output: opened plugin=pulse name="My Pulse Output" audio_format=44100:16:2
output: converting from 44100:24:2
client: [12] opened from 127.0.0.1:41901
client: [12] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
output: closed plugin=pulse name="My Pulse Output"
client: [12] command returned 0
client: [12] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [12] process command list returned 0
client: [12] closed
client: [13] opened from 127.0.0.1:41902
client: [13] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [13] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
client: [13] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [13] process command list returned 0
client: [13] closed
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
client: [14] opened from 127.0.0.1:41904
client: [14] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [14] command returned 0
client: [14] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [14] process command list returned 0
client: [14] closed
client: [15] opened from 127.0.0.1:41905
client: [15] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [15] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
client: [15] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [15] process command list returned 0
client: [15] closed
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
output: opened plugin=pulse name="My Pulse Output" audio_format=44100:16:2
output: converting from 44100:24:2
client: [16] opened from 127.0.0.1:41907
client: [16] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
output: closed plugin=pulse name="My Pulse Output"
client: [16] command returned 0
client: [16] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [16] process command list returned 0
client: [16] closed
client: [17] opened from 127.0.0.1:41908
client: [17] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [17] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
client: [17] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [17] process command list returned 0
client: [17] closed
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
output: opened plugin=pulse name="My Pulse Output" audio_format=44100:16:2
output: converting from 44100:24:2
client: [18] opened from 127.0.0.1:41910
client: [18] process command "stop"
playlist: stop
player: played "http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
output: closed plugin=pulse name="My Pulse Output"
client: [18] command returned 0
client: [18] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [18] process command list returned 0
client: [18] closed
client: [19] opened from 127.0.0.1:41911
client: [19] process command "play"
playlist: play 38:"http://prem1.sky.fm:80/lovemusic_hi?MYKEY"
client: [19] command returned 0
playlist: queue song 39:"http://prem1.sky.fm:80/mellowjazz_hi?MYKEY"
client: [19] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [19] process command list returned 0
client: [19] closed
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
icy_metadata: unknown icy-tag: 'StreamUrl'
output: opened plugin=pulse name="My Pulse Output" audio_format=44100:16:2
output: converting from 44100:24:2
client: [20] opened from 127.0.0.1:41913
client: [20] process command "stop"
playlist: stop

~0008754

cirrus (administrator)

Hm, this has been running for hours now, but never deadlocked. This must be some rare timing issue that can be reproduced only on some setups.

~0009112

supervacuo (reporter)

Last edited: 2014-11-16 17:56

View 2 revisions

I see this exact problem (down to the "Backtrace stopped: previous frame identical to this frame (corrupt stack?)" messages in gdb).

Raspberry Pi model B
Pidora 2014

mpd-0.18.16-2.fc20.armv6hl

I am also using pulseaudio output.

mpd.conf:

http://fpaste.org/151229/14832814/

(/mnt/finch/ is an NFSv4 mount)

Anything I can do to help debug?

~0009408

alethiophile (reporter)

I have what I believe to be the same issue. It appears only in pulse, and only in a TCP native-protocol pulse (as opposed to local). The database is local, and the bug is very reliably replicable after one or two iterations of that shell loop. I have replicated in 0.18.23, 0.19.9 and git head versions.

~0009437

alethiophile (reporter)

After some more investigation, I believe this is a pulse/libpulse bug at its root. Whenever the bug occurs, the destination pulse server spits out a number of messages of the form "Client sent non-aligned memblock", and I've seen this failure mode (and concomitant freeze in libpulse) in other clients as well (notably mpv). I've filed a bug with pulseaudio at https://bugs.freedesktop.org/show_bug.cgi?id=89883

~0009438

alethiophile (reporter)

Confirming that with a modification to the remote pulse server, the bug vanishes. The requisite modification is a simple reversal of the change at http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/src/pulsecore/protocol-native.c?id=22827a5e1e627115ae44a297be2ba5b35561700f

This is almost certainly not a good idea to run with, since that's apparently a security fix. I'll be pursuing this further with the pulse people.
+Notes

-Issue History
Date Modified Username Field Change
2014-09-05 07:00 craig New Issue
2014-09-05 07:00 craig Status new => assigned
2014-09-05 07:00 craig Assigned To => cirrus
2014-09-05 08:31 cirrus Note Added: 0008751
2014-09-05 17:13 craig Note Added: 0008753
2014-09-05 20:12 cirrus Note Added: 0008754
2014-11-16 15:44 supervacuo Note Added: 0009112
2014-11-16 17:56 supervacuo Note Edited: 0009112 View Revisions
2015-03-10 02:38 alethiophile Note Added: 0009408
2015-04-04 22:27 alethiophile Note Added: 0009437
2015-04-04 23:00 alethiophile Note Added: 0009438
+Issue History