Bugzilla – Bug 7492
Rhapsody Direct skips tracks
Last modified: 2009-07-31 10:17:56 UTC
I find that Rhapsody Direct frequently skips tracks when playing back a bunch of songs. Below is a logfile showing a skip. It played the first song, skipped the second, played the third. Note that all of these songs, including the one that failed to play, can be played by selecting them directly. [14:20:45.0760] Slim::Player::Squeezebox2::directHeaders (343) Processing 8 headers [14:20:45.0765] Slim::Plugin::RhapsodyDirect::ProtocolHandler::par seDirectHeaders (52) RhapsodyDirect header: Server: Apache/2.0.58 [14:20:45.0770] Slim::Plugin::RhapsodyDirect::ProtocolHandler::par seDirectHeaders (52) RhapsodyDirect header: Accept-Ranges: bytes [14:20:45.0774] Slim::Plugin::RhapsodyDirect::ProtocolHandler::par seDirectHeaders (52) RhapsodyDirect header: Content-Length: 2519164 [14:20:45.0866] Slim::Player::Squeezebox2::directHeaders (396) Got a stream type: wma bitrate: 128000 title: [14:20:45.0874] Slim::Player::Squeezebox2::directHeaders (455) Beginning direct stream! [14:20:45.0957] Slim::Player::Squeezebox::buffering (303) Buffering... 0 / 49152 [14:20:45.5011] Slim::Player::Squeezebox::buffering (303) Buffering... 1232 / 49152 [14:20:45.7821] Slim::Networking::Slimproto::_http_metadata_handle r (808) metadata (len: 204) [14:20:45.9155] Slim::Player::Squeezebox::buffering (303) Buffering... 51731 / 49152 [14:20:45.9238] Slim::Networking::Slimproto::_http_metadata_handle r (808) metadata (len: 264) [14:20:45.9263] Slim::Networking::Slimproto::_http_metadata_handle r (808) metadata (len: 132) [14:20:45.9311] Slim::Player::Protocols::MMS::setMetadata (271) Setting bitrate to 128 from WMA bitrate properties object [14:20:46.7084] Slim::Player::Source::trackStartEvent (1461) Got a track starting event [14:20:46.7089] Slim::Player::Source::trackStartEvent (1477) Song 0 has now started playing [14:20:46.7106] Slim::Player::Source::trackStartEvent (1505) Song queue is now 0 [14:23:13.6553] Slim::Player::Source::decoderUnderrun (582) 00:04:20:06:1a:f7: Decoder underrun while this mode: playout-play [14:23:13.6559] Slim::Player::Source::nextsong (1556) The next song is number 1, was 0 [14:23:13.6568] Slim::Player::Source::nextsong (1556) The next song is number 1, was 0 [14:23:13.6576] Slim::Plugin::RhapsodyDirect::ProtocolHandler::onD ecoderUnderrun (400) End of track, logging usage info (156 seconds)... [14:23:13.6595] Slim::Plugin::RhapsodyDirect::RPDS::rpds (72) 00:04:20:06:1a:f7 RPDS packet sent: 4 [14:23:14.2222] Slim::Plugin::RhapsodyDirect::RPDS::rpds_handler (126) 00:04:20:06:1a:f7 Got RPDS packet: \"\4" [14:23:14.2244] Slim::Plugin::RhapsodyDirect::RPDS::rpds (72) 00:04:20:06:1a:f7 RPDS packet sent: 3 [14:23:14.6399] Slim::Plugin::RhapsodyDirect::RPDS::rpds_handler (126) 00:04:20:06:1a:f7 Got RPDS packet: \"\3\x001http://llnw-584.listen.com/8/4/3/8/0/58708348.rad" [14:23:14.6802] Slim::Player::Source::skipahead (873) **skipahead: opening next song [14:23:14.6806] Slim::Player::Source::gotoNext (1206) Opening next song... [14:23:14.6815] Slim::Player::Source::nextsong (1556) The next song is number 1, was 0 [14:23:14.6829] Slim::Player::TranscodingHelper::getConvertCommand (201) undermax = 1, type = wma, squeezebox2 = 00:04:20:06:1a:f7 [14:23:14.6834] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: wma-wma-squeezebox2-00:04:20:06:1a:f7 [14:23:14.6839] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: wma-wma-*-00:04:20:06:1a:f7 [14:23:14.6843] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: wma-wma-squeezebox2-* [14:23:14.6847] Slim::Player::TranscodingHelper::enabledFormat (105) Checking to see if wma-wma-squeezebox2-* is enabled [14:23:14.6852] Slim::Player::TranscodingHelper::enabledFormat (113) There are 11 disabled formats... [14:23:14.6856] Slim::Player::TranscodingHelper::enabledFormat (119) Testing aif-mp3-*-* vs wma-wma-squeezebox2-* [removed similar lines for length] [14:23:14.6905] Slim::Player::TranscodingHelper::checkBin (148) Found command: - [14:23:14.6912] Slim::Player::TranscodingHelper::getConvertCommand (302) Matched Format: wma Type: wma Command: - [14:23:14.6917] Slim::Player::Source::gotoNext (1293) opening next song (old format: wma, new: wma) current playmode: playout-play [14:23:14.6924] Slim::Player::Source::streamingSongIndex (1350) Adding song index 1 to song queue [14:23:14.6929] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 1,0 [14:23:14.6933] Slim::Player::Source::skipahead (879) **skipahead: restarting [14:23:14.6938] Slim::Player::Source::playmode (298) 00:04:20:06:1a:f7: Switching to mode play from playout-play [14:23:14.6946] Slim::Player::Source::resetSong (1595) Resetting song buffer. [14:23:14.6998] Slim::Player::Source::openSong (1690) Trying to open: rhapd://Tra.12689351.wma [14:23:14.7308] Slim::Player::Source::playmode (401) 00:04:20:06:1a:f7 New play mode: play [14:23:14.7386] Slim::Player::Squeezebox::stream (1013) This player supports direct streaming for rhapd://Tra.12689351.wma as http://llnw-584.listen.com/8/4/3/8/0/58708348.rad, let's do it. [14:23:14.7586] Slim::Player::Squeezebox::stream (1044) setting up direct stream (3496976443:80) autostart: 3. [14:23:14.7591] Slim::Player::Squeezebox::stream (1045) request string: GET /8/4/3/8/0/58708348.rad HTTP/1.0 Cache-Control: no-cache Connection: close Accept: */* Host: llnw-584.listen.com User-Agent: iTunes/4.7.1 (Windows; N; Windows XP; 586; EN; cp1252) SqueezeCenter/7.0/17793 Icy-Metadata: 1 [14:23:14.7608] Slim::Player::Source::playmode (556) 00:04:20:06:1a:f7: Current playmode: play [14:23:14.8460] Slim::Player::Squeezebox2::directHeaders (284) Processing headers for direct streaming: HTTP/1.0 200 OK Server: Apache/2.0.58 Accept-Ranges: bytes Content-Length: 2679260 Content-Type: text/plain Age: 224119 Date: Tue, 11 Mar 2008 18:22:58 GMT Last-Modified: Wed, 29 Nov 2006 19:42:31 GMT Connection: close [14:23:14.8466] Slim::Player::Squeezebox2::directHeaders (343) Processing 8 headers [14:23:14.8471] Slim::Plugin::RhapsodyDirect::ProtocolHandler::par seDirectHeaders (52) RhapsodyDirect header: Server: Apache/2.0.58 [14:23:14.8475] Slim::Plugin::RhapsodyDirect::ProtocolHandler::par seDirectHeaders (52) RhapsodyDirect header: Accept-Ranges: bytes [14:23:14.8480] Slim::Plugin::RhapsodyDirect::ProtocolHandler::par seDirectHeaders (52) RhapsodyDirect header: Content-Length: 2679260 [14:23:14.8571] Slim::Player::Squeezebox2::directHeaders (396) Got a stream type: wma bitrate: 128000 title: [14:23:14.8577] Slim::Player::Squeezebox2::directHeaders (455) Beginning direct stream! [14:23:16.0946] Slim::Networking::Slimproto::_http_metadata_handle r (808) metadata (len: 204) [14:23:16.1578] Slim::Networking::Slimproto::_http_metadata_handle r (808) metadata (len: 264) [14:23:16.1603] Slim::Networking::Slimproto::_http_metadata_handle r (808) metadata (len: 132) [14:23:16.1681] Slim::Player::Protocols::MMS::setMetadata (271) Setting bitrate to 128 from WMA bitrate properties object [14:23:16.3339] Slim::Player::Source::decoderUnderrun (582) 00:04:20:06:1a:f7: Decoder underrun while this mode: playout-play [14:23:16.3346] Slim::Player::Source::nextsong (1556) The next song is number 2, was 1 [14:23:16.3353] Slim::Player::Source::decoderUnderrun (595) Track failed before playback, marking as played [14:23:16.3359] Slim::Player::Source::playmode (298) 00:04:20:06:1a:f7: Switching to mode playout-play from playout-play [14:23:16.3363] Slim::Player::Source::playmode (305) Already in playmode playout-play : ignoring mode change [14:23:16.3369] Slim::Player::Source::nextsong (1556) The next song is number 2, was 1 [14:23:16.3377] Slim::Plugin::RhapsodyDirect::ProtocolHandler::onD ecoderUnderrun (400) End of track, logging usage info (166 seconds)... [14:23:16.3396] Slim::Plugin::RhapsodyDirect::RPDS::rpds (72) 00:04:20:06:1a:f7 RPDS packet sent: 4 [14:23:16.3464] Slim::Plugin::RhapsodyDirect::RPDS::rpds_handler (126) 00:04:20:06:1a:f7 Got RPDS packet: \"\xFC" [14:23:16.3473] Slim::Plugin::RhapsodyDirect::RPDS::rpds_handler (269) 00:04:20:06:1a:f7 Received RPDS -4, SSL connection already in use, retrying later [14:23:18.3601] Slim::Plugin::RhapsodyDirect::RPDS::rpds_resend (317) 00:04:20:06:1a:f7 Re-sending RPDS packet: "\4\x03166" [14:23:18.3615] Slim::Plugin::RhapsodyDirect::RPDS::rpds (72) 00:04:20:06:1a:f7 RPDS packet sent: 4 [14:23:18.8193] Slim::Plugin::RhapsodyDirect::RPDS::rpds_handler (126) 00:04:20:06:1a:f7 Got RPDS packet: \"\4" [14:23:18.8217] Slim::Plugin::RhapsodyDirect::RPDS::rpds (72) 00:04:20:06:1a:f7 RPDS packet sent: 3 [14:23:19.2335] Slim::Plugin::RhapsodyDirect::RPDS::rpds_handler (126) 00:04:20:06:1a:f7 Got RPDS packet: \"\3\x001http://llnw-578.listen.com/7/8/2/8/0/58708287.rad" [14:23:19.2724] Slim::Player::Source::skipahead (873) **skipahead: opening next song [14:23:19.2729] Slim::Player::Source::gotoNext (1206) Opening next song... [14:23:19.2735] Slim::Player::Source::nextsong (1556) The next song is number 2, was 1 [14:23:19.2747] Slim::Player::TranscodingHelper::getConvertCommand (201) undermax = 1, type = wma, squeezebox2 = 00:04:20:06:1a:f7
Matt: Have you been able to repo this with the latest Daily build of 7.0.1? I just tried and could not see an error in my log, or in the actual play list skipping tracks.
I'll try it. I certainly have been reproing it out the wazoo today with build 17939.
Yes, it still skips. To try to make it easier on myself to tell, I put on an album I've heard a zillion times, so that if it skipped a track I'd know. It did.
Andy: I have been able to replicate this error, however, not on the frequency that Matt is reporting. Which logs would help you diagnose the issue?
plugin.rhapsodydirect, player.source, player.streaming.direct Please don't paste logs in Bugzilla as they become unreadable, but attach them to the bug, thanks. :)
Created attachment 3147 [details] shows skip of third track shows skip of third track
Comment on attachment 3147 [details] shows skip of third track skip this one, I didn't save the cut down version.
Created attachment 3148 [details] use this one - skip of 3rd track shows skip of 3rd track
Created attachment 3149 [details] Rhapsody Direct skip log Track within a Rhapsody playlist started playing and skipped a few seconds into the song. See log around 12:15 to 12:16 This is with SqueezeCenter Version: 7.0 - 17759 - Windows XP - EN - cp1255
I had the following log settings at DEBUG: plugin.rhapsodydirect, player.source, player.streaming.direct I had "show buffer fullness" in the player's display settings Play a large Rhapsody playlist. A good candidate is Top Tracks of Willie Nelson which includes over 1000 tracks. Then there are 2 possible methods to reproduce: 1. Passive approach: Just leave it alone playing. Take a look a the SB3 display from time to time, at some point it will hang with no sound. 2. Proactive approach: Skip to next track. If it starts playing (with sound) skip to next track. Do so until SB3 hangs with no sound. It might occur on track #3 or #30 or #300...
Oops, please ignore my previous comment #10, it is for a different bug, sorry
The theory on this is that there are network problems that cause the device to give up and try the next track. We're working on improved reporting for this case. Do the users here think that might have been the underlying cause?
When I had network problems in the past I did observe that Rhapsody tracks that encountered severe buffering problems tended to be given up mid-song and skip to next track. However this case seems different. As far as I can tell I do not have any network-related problems these days. The 'show buffer display' counters show excellent buffering numbers. When the bug happens the track appears on the SB3 display, and then skips before emitting any sound. While a networking issue may be the cause, I'm pretty sure it is an actual bug, and not something that can simply be blamed on poor networks.
I can't say for sure whether it's network problems. I have been having a lot of network problems and rebuffering lately, the cause of which I do not understand. However, this track-skipping started before I began having all of the network problems. In addition, it didn't ever seem to happen in mid-track, but always right at the start -- a track simply didn't get played, or perhaps the first half second would be played. So I'm tempted to say either that it isn't a network problem, or that if it is, it still requires a fix from you folks, something in the nature of a longer timeout, larger buffer, I don't know what. I'm sorry to see this is being put off to 7.1, as I think it's a serious problem.
I rewrote a bit of the way Rhapsody handles track advances today to fix a bug with synced channels, please retest this bug with tonight's nightly (7.0.2 or higher).
If anyone sees this again, please reopen the bug!
Created attachment 3511 [details] server log showing skip of Rhapsody track
Hello, I've finally gotten a chance to test this, and I am still having the track-skip problem. I've uploaded a server.log that shows the skip. If you search through the log for "Song queue is now" you'll find these entries; Song queue is now 0 Song queue is now 0 Song queue is now 0 Song queue is now 1,0 Song queue is now 1 Song queue is now 2,1 Song queue is now 2 Song queue is now 3,2 Song queue is now 3 Song queue is now 4,3 Song queue is now 4 Song queue is now 5,4 Song queue is now 6,5 Between those last two entries is where the track was skipped. 25 lines up or so from that last entry you can see things like "Decoder underrun while this mode: playout-play" and "Track failed before playback, marking as played."
Here's my version info fyi: SqueezeCenter Version: 7.0.2 - 21032 @ Sat Jun 28 00:24:02 PDT 2008 - Windows XP - EN - cp1252 Server IP address: 192.168.1.6 Perl Version: 5.8.8 MSWin32-x86-multi-thread MySQL Version: 5.0.22-community-nt
We need to find a way to reproduce this.
I have yet to make it through Queen's "A Night at the Opera" without it skipping a track . . . you could try that. Also, I'm willing to try an even more debug-printing release if you want to make one. But probably you're saying the bug occurs inconsistently, not that you can't see what's happening.
I'll give that album a try.
This album plays just fine for me. I think I'll make a debug build of firmware 88 tomorrow that you can run to get some additional log output.
Matt / Y360: Can you both please re-test this with 7.2 nightly build? I have not been able to reproduce this using the 7.2 builds with latest firmwares. Please make sure you have debug logging enabled as Andy points out. If you see the errors, please attache the relevant sections, then re-open this bug. Thank you.
Verified fixed in SqueezeCenter 7.2.1-23472 Controller 7.2 r3070 Receiver r48 SB2/3 r113 Transporter r63 Boom r33
This bug has been fixed in the 7.3.0 release version of SqueezeCenter! Please download the new version from http://www.slimdevices.com/su_downloads.html if you haven't already. If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.
Reduce number of active targets for SC