Bugzilla – Bug 3753
Slimserver fails to advance to next song in playlist
Last modified: 2009-01-29 09:47:09 UTC
SlimServer Version: 6.5b1 - 8435 - Linux - EN - utf8 Player Firmware Version: 58 This may not be related to the latest version I have upgraded to the latest build to ensure it has not been fixed. When a playlist is created it will play the first song. At the end of that song it will stop. If I hit SKIP it may play the next song, but not always. I may have to hit the play on the track to play it.
I'm not seeing this problem, Dave. Are these saved playlists, or just random playlists, or what? Also, what kind of files are you playing? (mp3, flac, etc)
This is just standard operation. Starting with an empty queue to the squeezebox I select an album to play. It queues up the 10 songs from the album and plays the first track. At the end of track 1 it stops on that song and does not advance to track 2. Clicking skip on the player WEB UI may start track 2 playing. It may set track to to "Now Playing" but not start playing. So at best you will have to click SKIP 10 times to play the album. You may have to restart slimserver.pl to get it to play the current track. All songs are recorded as MP3.
try turning on d_source in server settings->debugging. you can then attach /tmp/slimserver.log to this report. hopefully it will show why the server has decided to stop at the end of your tracks.
Created attachment 1352 [details] Log file as requested You will see from the log that I had to skip the tracks to force the server to playout. It appears that a player event is being missed
I spent the afternoon playing with this, don't tell the wife. As I see it the Source.pm routine gotoNext puts the player into "play-playout" mode. Source::decoder_underun calls skipahead to find the track as the playout completes, and puts the player into "play" mode. Whats missing is something to restart the streaming, of the new track. The player can only be restarted with the remote using "forward" or the web interface using "SKIP".
The following is a better trace:- 2006-07-16 17:13:50.0087 **skipahead: restarting 2006-07-16 17:13:50.0089 00:04:20:06:98:13: Switching to mode play from playout-play 2006-07-16 17:13:50.0092 Backtrace: frame 0: Slim::Player::Source::playmode (/usr/local/slimserver/Slim/Player/Source.pm line 626) frame 1: Slim::Player::Source::skipahead (/usr/local/slimserver/Slim/Player/Source.pm line 574) frame 2: Slim::Player::Source::decoderUnderrun (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 581) frame 3: (eval) (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 581) frame 4: Slim::Networking::Slimproto::_stat_handler (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 321) frame 5: Slim::Networking::Slimproto::client_readable (/usr/local/slimserver/Slim/Networking/Select.pm line 168) frame 6: Slim::Networking::Select::select (/usr/local/slimserver/slimserver.pl line 499) frame 7: main::idle (/usr/local/slimserver/slimserver.pl line 452) frame 8: main::main (/usr/local/slimserver/slimserver.pl line 1048) 2006-07-16 17:13:50.0357 openSong on: file:///usr/local/mp3/Wingspan_%20Hits/Coming%20Up%20(Live%20Version).mp3 2006-07-16 17:13:50.0367 openSong: duration: [231.289] size: [3700617] endian [] offset: [2167] for file:///usr/local/mp3/Wingspan_%20Hits/Coming%20Up%20(Live%20Version).mp3 2006-07-16 17:13:50.0370 Setting maxBitRate for musicbox to: 0 2006-07-16 17:13:50.0373 Setting maxBitRate for musicbox to: 0 2006-07-16 17:13:50.0378 Setting maxBitRate for musicbox to: 0 2006-07-16 17:13:50.0381 Setting maxBitRate for musicbox to: 0 2006-07-16 17:13:50.0383 undermax = 1, type = mp3, squeezebox2 = 00:04:20:06:98:13 2006-07-16 17:13:50.0386 checking formats for: mp3-wma-squeezebox2-00:04:20:06:98:13 2006-07-16 17:13:50.0388 checking formats for: mp3-wma-*-00:04:20:06:98:13 2006-07-16 17:13:50.0389 checking formats for: mp3-wma-squeezebox2-* 2006-07-16 17:13:50.0391 checking formats for: mp3-wma-*-* 2006-07-16 17:13:50.0393 checking formats for: mp3-ogg-squeezebox2-00:04:20:06:98:13 2006-07-16 17:13:50.0395 checking formats for: mp3-ogg-*-00:04:20:06:98:13 2006-07-16 17:13:50.0397 checking formats for: mp3-ogg-squeezebox2-* 2006-07-16 17:13:50.0398 checking formats for: mp3-ogg-*-* 2006-07-16 17:13:50.0400 checking formats for: mp3-flc-squeezebox2-00:04:20:06:98:13 2006-07-16 17:13:50.0402 checking formats for: mp3-flc-*-00:04:20:06:98:13 2006-07-16 17:13:50.0404 checking formats for: mp3-flc-squeezebox2-* 2006-07-16 17:13:50.0405 checking formats for: mp3-flc-*-* 2006-07-16 17:13:50.0407 checking formats for: mp3-aif-squeezebox2-00:04:20:06:98:13 2006-07-16 17:13:50.0409 checking formats for: mp3-aif-*-00:04:20:06:98:13 2006-07-16 17:13:50.0411 checking formats for: mp3-aif-squeezebox2-* 2006-07-16 17:13:50.0413 checking formats for: mp3-aif-*-* 2006-07-16 17:13:50.0414 checking formats for: mp3-wav-squeezebox2-00:04:20:06:98:13 2006-07-16 17:13:50.0416 checking formats for: mp3-wav-*-00:04:20:06:98:13 2006-07-16 17:13:50.0418 checking formats for: mp3-wav-squeezebox2-* 2006-07-16 17:13:50.0420 checking formats for: mp3-wav-*-* 2006-07-16 17:13:50.0421 checking formats for: mp3-mp3-squeezebox2-00:04:20:06:98:13 2006-07-16 17:13:50.0423 checking formats for: mp3-mp3-*-00:04:20:06:98:13 2006-07-16 17:13:50.0425 checking formats for: mp3-mp3-squeezebox2-* 2006-07-16 17:13:50.0427 checking formats for: mp3-mp3-*-* 2006-07-16 17:13:50.0428 Checking to see if mp3-mp3-*-* is enabled 2006-07-16 17:13:50.0431 enabled 2006-07-16 17:13:50.0433 Found command: - 2006-07-16 17:13:50.0435 Setting maxBitRate for musicbox to: 0 2006-07-16 17:13:50.0438 Setting maxBitRate for musicbox to: 0 2006-07-16 17:13:50.0440 Matched Format: mp3 Type: mp3 Command: - 2006-07-16 17:13:50.0442 openSong: this is an mp3 file: file:///usr/local/mp3/Wingspan_%20Hits/Coming%20Up%20(Live%20Version).mp3 2006-07-16 17:13:50.0444 file type: mp3 format: mp3 inrate: 128 maxRate: 0 2006-07-16 17:13:50.0445 command: - 2006-07-16 17:13:50.0448 openSong: opening file /usr/local/mp3/Wingspan_ Hits/Coming Up (Live Version).mp3 2006-07-16 17:13:50.0450 openSong: seeking in 2167 into /usr/local/mp3/Wingspan_ Hits/Coming Up (Live Version).mp3 2006-07-16 17:13:50.0453 openSong: Streaming with format: mp3 2006-07-16 17:13:50.0537 00:04:20:06:98:13 New play mode: play 2006-07-16 17:13:50.0608 00:04:20:06:98:13: Current playmode: play 2006-07-16 17:13:58.8811 Setting maxBitRate for musicbox to: 0 2006-07-16 17:13:58.8815 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:04.3351 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:04.3356 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:09.7298 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:09.7303 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:15.1394 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:15.1398 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:20.5459 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:20.5463 Setting maxBitRate for musicbox to: 0
The stream should not have to be restarted. Playout-play is a mode that is meant to let the buffer run down, but intended to continue playing after. playout-stop is the mode that stops the stream. of course, some type of problem could cause any mode to stop. in your second trace, are you saying that Wingspan_%20Hits/Coming%20Up%20(Live%20Version).mp3 did not play? Is the later opensong due to you pressing PLAY?
See comment 5 below. The decode underrun calls skipahead and correctly opens the next song 2006-07-16 17:13:50.0448 openSong: opening file /usr/local/mp3/Wingspan_ Hits/Coming Up (Live Version).mp3 The playout-play correctly turns to play mode and we see the "skipahead restarting" event. So the slimserver is ready to start streaming, but streaming does not start. Currently I can only restart streaming of the next track by placing the player into STOP and issuing a SKIP on the web interface or a forward via the remote. 2006-07-16 17:13:50.0608 00:04:20:06:98:13: Current playmode: play <----mode has been set to play 2006-07-16 17:13:58.8811 Setting maxBitRate for musicbox to: 0 <-player is idle streaming not started 2006-07-16 17:13:58.8815 Setting maxBitRate for musicbox to: 0 <-would expect to see about 4 of these before 2006-07-16 17:14:04.3351 Setting maxBitRate for musicbox to: 0 <-song streaming starts. Player displays now playing 2006-07-16 17:14:04.3356 Setting maxBitRate for musicbox to: 0 <-but no stream is being sent to the player 2006-07-16 17:14:09.7298 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:09.7303 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:15.1394 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:15.1398 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:20.5459 Setting maxBitRate for musicbox to: 0 2006-07-16 17:14:20.5463 Setting maxBitRate for musicbox to: 0
One additional though was that this may be caused by the version of perl that is running on the server box [root@inca ~]# perl -v This is perl, v5.8.8 built for x86_64-linux-thread-multi
I notice that this case has been reasigned but have not seen an update.
KDF or Dan do either of you have any theories about how I might be able to reproduce this?
Also if you guys need me to focus on how any bits of code are running I am happy to hack the code. What I don't know is what event you would expect to pickup and restary the stream. Looks to me that after the playout the server correctly finds the next song and the decoder_underrun switches playmode to play but there is some reason that stops streaming starting.
the problem is, this isn't a generic problem with restarting the stream. I regularly play many songs,and I can't think of any way to reprduce this problem. Forcing a restart can only work if we understand the cause, in order to flag that cause and trigger a restart. I'm can't even think of what debug settings might shed more light on the problem.
Created attachment 1354 [details] New log This log is a debug with d_source + protocol. Its detailed but as this bug is now 100% reproucable. Plays first track of album (sometimes doesn't do that) but never starts track 2
Created attachment 1356 [details] Interesting disconnect reported I ran the above trace again this time I noticed a disconnect in the protocol stream after the second song tries to start streaming. Is this normal? 2006-07-19 23:09:05.3424 sending strm frame of length: 76 request string: GET /stream.mp3?player=00:04:20:06:98:13 HTTP/1.0 . . . 2006-07-19 23:09:05.3918 Squeezebox got disconnection on the data channel why: Connection closed normally
Hmm. Does your squeezebox seem to be behaving normally during all this (other than stopping playing)? It doesn't lock up or reboot or anything?
Squeezebox looks fine, no lockups or reboots. It plays tracks fine, just stops at end of track stuck in play mode.
You might have more luck, Dave, in the developers forum of the message board. I admit I don't know the answer to your question. I'm more likely to approach it from a support standpoint, with things like doing a factory reset on your player and looking at your network connectivity. At the moment, you seem to be the only person reporting this bug, but I'll leave it open for now in case more reports show up.
Good news I have got to the bottom of this one. I found a reference to problems running the squeezebox off a draytek wireless router. I have two access points in the house and found that the squeezebox was flipping between the two when being dropped by the draytek. I tried the beta firmware on the draytek and it was better but not perfect. I renamed my netgear access points ssid and now connect my squeezbox through that and it is working fine. Nice thing is I know alot more about the slimserver perl code now than if it had worked first time out of the box
Ok! Good to know.