0001611: Reproducable hang in MPD when waiting for a stream and changing playlist

(0001756)
Avuton Olrich (administrator)
2007-11-15 21:36

To clear up my prior statements, by 'crash' I mean MPD no longer responds to clients, does not play music.

(0001761)
Avuton Olrich (administrator)
2007-11-17 19:58

Whatever's causing this bug, I suspect it has something to do with why the ogg streaming starts /so/ slowly. Any stream from jamendo that takes a while to start with MPD starts in msec in ogg123.

(0001764)
qball (administrator)
2007-11-18 11:47

reproducing this bug, I get this the same timeout (my_usleep) for 2 processes, but If I trace the 3rd I see this:

recvfrom(4, "^n\201\200\0\1\0\1\0\0\0\0\tstream1-4\7jamendo\3c"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("195.121.1.34")}, [16]) = 55
close(4) = 0
socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 4
fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR)
fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(4, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("88.191.47.114")}, 16) = -1 EINPROGRESS (Operation now in progress)
select(5, NULL, [4], [4], {0, 0}) = 0 (Timeout)
select(5, NULL, [4], [4], {0, 0}) = 0 (Timeout)
close(4) = 0
socket(PF_NETLINK, SOCK_RAW, 0) = 4
bind(4, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0
getsockname(4, {sa_family=AF_NETLINK, pid=4569, groups=00000000}, [12]) = 0
time(NULL) = 1195406522
sendto(4, "\0\0\0\24\0\26\3\1G@t\272\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20
recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\0\0\0000\0\24\0\2G@t\272\0\0\21\331\2\10\200\376\0\0\0\1\0\10\0\1\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 108
recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\0\0\0@\0\24\0\2G@t\272\0\0\21\331\n\200\200\376\0\0\0\1\0\24\0\1\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 128
recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\0\0\0\24\0\3\0\2G@t\272\0\0\21\331\0\0\0\0\0\0\0\1\0\24\0\1\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20
close(4) = 0
open("/etc/hosts", O_RDONLY|0x80000 /* O_??? */) = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=197, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x30006000
read(4, "# Do not remove the following li"..., 4096) = 197
read(4, "", 4096) = 0
close(4) = 0
munmap(0x30006000, 4096) = 0
open("/etc/hosts", O_RDONLY|0x80000 /* O_??? */) = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=197, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x30007000
read(4, "# Do not remove the following li"..., 4096) = 197
read(4, "", 4096) = 0
close(4) = 0
munmap(0x30007000, 4096) = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("195.121.1.34")}, 28) = 0
fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR)
fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
send(4, "oW\1\0\0\1\0\0\0\0\0\0\tstream1-4\7jamendo\3c"..., 39, MSG_NOSIGNAL) = 39

This suggests that mpd is still trying to chat up jamendo.

(0001765)
qball (administrator)
2007-11-18 11:54

Further investigation shows that initHTTPConnection gets called over and over again.
think several thousand times a minute (checked!).
if you do a killall mpd, it will nicely shutdown.

(0001766)
qball (administrator)
2007-11-18 12:01

the initHTTPConnection gets called from inputStream_httpbuffer
More investigation after dinner.

(0001767)
qball (administrator)
2007-11-18 13:03

More investigations leads that the calls to the http buffer are caused by a seek request. (from inputStream_httpSeek)

(0001768)
qball (administrator)
2007-11-18 13:24

Ok, the problem seems to be that the ogg decoder tries todo a seek on the ogg stream. (It seeks to severall points in the ogg and the end. (I can get more detailed info about this using the mserver plugin of gmpc, I can easily print out the extact seek positions etc, and the retrieved data..))
Streams from f.e. jamendo do not seem to like this seeking, and it will take an awfull lot of time todo so.
If during this time the playing is stopped, the oggvorbis decoder will still try to seek. and hanging mpd.
Why it does not get correctly destroyed I don't know.

(0001769)
qball (administrator)
2007-11-18 14:12

A possible fix here: http://images.qballcow.nl/fix_canceling_ogg_stream.patch [^]

(0001801)
qball (administrator)
2007-11-28 15:23

Should be fixed in svn.

Issue History
Date Modified	Username	Field	Change
2007-11-15 21:33	Avuton Olrich	New Issue
2007-11-15 21:33	Avuton Olrich	Status	new => assigned
2007-11-15 21:33	Avuton Olrich	Assigned To	=> shank
2007-11-15 21:36	Avuton Olrich	Note Added: 0001756
2007-11-15 21:36	Avuton Olrich	Summary	Reproducable crash in MPD when waiting for a stream and changing playlist => Reproducable hang in MPD when waiting for a stream and changing playlist
2007-11-15 21:53	Avuton Olrich	Relationship added	related to 0001609
2007-11-15 22:11	Avuton Olrich	Relationship added	related to 0001607
2007-11-17 19:58	Avuton Olrich	Note Added: 0001761
2007-11-18 11:47	qball	Note Added: 0001764
2007-11-18 11:47	qball	Issue Monitored: qball
2007-11-18 11:54	qball	Note Added: 0001765
2007-11-18 12:01	qball	Note Added: 0001766
2007-11-18 13:03	qball	Note Added: 0001767
2007-11-18 13:24	qball	Note Added: 0001768
2007-11-18 14:12	qball	Note Added: 0001769
2007-11-28 15:23	qball	Status	assigned => closed
2007-11-28 15:23	qball	Note Added: 0001801
2007-11-28 15:23	qball	Resolution	open => fixed

Notes
(0001756) Avuton Olrich (administrator) 2007-11-15 21:36	To clear up my prior statements, by 'crash' I mean MPD no longer responds to clients, does not play music.

(0001761) Avuton Olrich (administrator) 2007-11-17 19:58	Whatever's causing this bug, I suspect it has something to do with why the ogg streaming starts /so/ slowly. Any stream from jamendo that takes a while to start with MPD starts in msec in ogg123.

(0001764) qball (administrator) 2007-11-18 11:47	reproducing this bug, I get this the same timeout (my_usleep) for 2 processes, but If I trace the 3rd I see this: recvfrom(4, "^n\201\200\0\1\0\1\0\0\0\0\tstream1-4\7jamendo\3c"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("195.121.1.34")}, [16]) = 55 close(4) = 0 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 4 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(4, F_SETFL, O_RDWR\|O_NONBLOCK) = 0 connect(4, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("88.191.47.114")}, 16) = -1 EINPROGRESS (Operation now in progress) select(5, NULL, [4], [4], {0, 0}) = 0 (Timeout) select(5, NULL, [4], [4], {0, 0}) = 0 (Timeout) close(4) = 0 socket(PF_NETLINK, SOCK_RAW, 0) = 4 bind(4, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0 getsockname(4, {sa_family=AF_NETLINK, pid=4569, groups=00000000}, [12]) = 0 time(NULL) = 1195406522 sendto(4, "\0\0\0\24\0\26\3\1G@t\272\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\0\0\0000\0\24\0\2G@t\272\0\0\21\331\2\10\200\376\0\0\0\1\0\10\0\1\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 108 recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\0\0\0@\0\24\0\2G@t\272\0\0\21\331\n\200\200\376\0\0\0\1\0\24\0\1\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 128 recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\0\0\0\24\0\3\0\2G@t\272\0\0\21\331\0\0\0\0\0\0\0\1\0\24\0\1\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 close(4) = 0 open("/etc/hosts", O_RDONLY\|0x80000 /* O_??? /) = 4 fstat64(4, {st_mode=S_IFREG\|0644, st_size=197, ...}) = 0 mmap(NULL, 4096, PROT_READ\|PROT_WRITE, MAP_PRIVATE\|MAP_ANONYMOUS, -1, 0) = 0x30006000 read(4, "# Do not remove the following li"..., 4096) = 197 read(4, "", 4096) = 0 close(4) = 0 munmap(0x30006000, 4096) = 0 open("/etc/hosts", O_RDONLY\|0x80000 / O_??? */) = 4 fstat64(4, {st_mode=S_IFREG\|0644, st_size=197, ...}) = 0 mmap(NULL, 4096, PROT_READ\|PROT_WRITE, MAP_PRIVATE\|MAP_ANONYMOUS, -1, 0) = 0x30007000 read(4, "# Do not remove the following li"..., 4096) = 197 read(4, "", 4096) = 0 close(4) = 0 munmap(0x30007000, 4096) = 0 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4 connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("195.121.1.34")}, 28) = 0 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(4, F_SETFL, O_RDWR\|O_NONBLOCK) = 0 poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 send(4, "oW\1\0\0\1\0\0\0\0\0\0\tstream1-4\7jamendo\3c"..., 39, MSG_NOSIGNAL) = 39 This suggests that mpd is still trying to chat up jamendo.

(0001765) qball (administrator) 2007-11-18 11:54	Further investigation shows that initHTTPConnection gets called over and over again. think several thousand times a minute (checked!). if you do a killall mpd, it will nicely shutdown.

(0001766) qball (administrator) 2007-11-18 12:01	the initHTTPConnection gets called from inputStream_httpbuffer More investigation after dinner.

(0001767) qball (administrator) 2007-11-18 13:03	More investigations leads that the calls to the http buffer are caused by a seek request. (from inputStream_httpSeek)

(0001768) qball (administrator) 2007-11-18 13:24	Ok, the problem seems to be that the ogg decoder tries todo a seek on the ogg stream. (It seeks to severall points in the ogg and the end. (I can get more detailed info about this using the mserver plugin of gmpc, I can easily print out the extact seek positions etc, and the retrieved data..)) Streams from f.e. jamendo do not seem to like this seeking, and it will take an awfull lot of time todo so. If during this time the playing is stopped, the oggvorbis decoder will still try to seek. and hanging mpd. Why it does not get correctly destroyed I don't know.

(0001769) qball (administrator) 2007-11-18 14:12	A possible fix here: http://images.qballcow.nl/fix_canceling_ogg_stream.patch [^]

(0001801) qball (administrator) 2007-11-28 15:23	Should be fixed in svn.