PDA

View Full Version : Rhapsody skips tracks



smr888
2008-03-11, 07:33
Anyone else notice Rhapsody skipping tracks during playback? Many times I'll listen to a group of songs and notice that some of them simply didn't play. Sometimes I'll hear a little blip of music at the beginning of a song before it skips to the next one. At least once I caught it skipping two consecutive tracks.

Is there some debug flag I can use to try to track this problem down, or something else I can do to repair the problem?

SqueezeCenter Version: 7.0 - 17737 - Windows XP - EN - cp1252

not the absolute most recent, but relatively new.

andyg
2008-03-11, 07:38
On Mar 11, 2008, at 10:33 AM, smr888 wrote:

>
> Anyone else notice Rhapsody skipping tracks during playback? Many
> times
> I'll listen to a group of songs and notice that some of them simply
> didn't play. Sometimes I'll hear a little blip of music at the
> beginning of a song before it skips to the next one. At least once I
> caught it skipping two consecutive tracks.
>
> Is there some debug flag I can use to try to track this problem down,
> or something else I can do to repair the problem?
>
> SqueezeCenter Version: 7.0 - 17737 - Windows XP - EN - cp1252
>
> not the absolute most recent, but relatively new.


You can set the following log settings to DEBUG:
plugin.rhapsodydirect, player.source, player.streaming.direct

smr888
2008-03-11, 11:33
OK, here's the log showing where it skips a track (apparently). It played one, skipped one, played one. The lines starting with [14:20...] are presumably the successful play, then comes a sequence of [14:23...] where the error should have occurred. I assume it's the "decoder underrun" business.

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

smr888
2008-03-13, 07:16
I logged this as a bug (7492). I hope someone will look at it soon, as it seems fairly serious, to me anyway.