Bugzilla – Bug 12653
Pandora Streams playing one song while SC reports another...
Last modified: 2009-10-05 14:27:16 UTC
Using the latest 7.4 nightly, Pandora seems broken. Currently my SqueezeCenter is 4-songs back in reporting which one is playing. Ie: Song 1: Greenday Song 2: Chilli Peppers Song 3: Madonna Song 4: Sum41 If song 4 is playing, song 1 is the on the screen... Here are some captures from the pandora debug logging [09-07-02 08:13:21.0005] Slim::Utils::Prefs::Namespace::savenow (304) saving prefs for server to /Users/diranged/Library/Application Support/Squeezebox Server/server.prefs [09-07-02 08:13:23.3069] Slim::Plugin::Pandora::ProtocolHandler::getNextTrack (165) Getting next track from SqueezeNetwork for stationid=96201477886713760 [09-07-02 08:13:23.5047] Slim::Plugin::Pandora::ProtocolHandler::gotNextTrack (190) Got Pandora track: { albumArtUrl => "http://images-sjl-1.pandora.com/images/public/amz/3/2/2/1/075596201223_301W_300H.jpg", albumDetailUrl => "http://www.pandora.com/music/album/3rd+eye+blind/3rd+eye+blind?ad=0:28:1:94061:ip,ip:0", albumName => "Third Eye Blind", allowFeedback => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"), amazonAlbumAsin => "B000002HOK", "amazonAlbumDigitalAsin" => "B00124FP5S", amazonAlbumUrl => "http://www.amazon.com/dp/B000002HOK/?", "amazonSongDigitalAsin" => "B00124D8IY", artistDetailUrl => "http://www.pandora.com/music/artist/3rd+eye+blind?ad=0:28:1:94061:ip,ip:0", artistName => "Third Eye Blind", audioUrl => "http://audio-sjl-t1-2.pandora.com/access/?version=4&lid=72228768&token=X9Y1iEwvM9RxdZtNHwYlZcoPRX1o%2BOWS5VknXPsyzGe%2Fm6mQ4VGrAFCe8uND4LCybdj7fhek1C7xn68dKB4%2F%2F%2FitVJRDF4PjNiWLyZXZfj0qJC7VIaPyB32U3Y4%2FVQ%2FmP%2B7Ld0EI%2FMWW6pP4uGXSFq7THkB6mMcDbNbZlhj6K8bxj0L2r%2FGz3McaSui2uyzxlmRIxSOOtuulC%2BRYsg2iKvYUesJ1TTWsgbuJv3UVcoJBE2wRPcXfTW8jjoQaEdAoM7UnpjMDDYsJ5Q7h4kAp%2BgFCbXcRq8gzAINBV5JM3ecIlSQMZp0afMFQCb8EPUBb", canSkip => 1, itunesSongUrl => "http://click.linksynergy.com/fs-bin/stat?id=FLenzF8lvbI&offerid=78941&type=3&subid=0&tmpid=1826&RD_PARM1=http%253A%252F%252Fphobos.apple.com%252FWebObjects%252FMZStore.woa%252Fwa%252FviewAlbum%253Fi%253D271978748%2526id%253D271978738%2526partnerId%3D30", secs => 273, songDetailUrl => "http://www.pandora.com/music/song/3rd+eye+blind/jumper?ad=0:28:1:94061:ip,ip:0", songName => "Jumper", songRating => 0, stationId => "96201477886713760", trackGain => "-3.55", trackToken => "d800b889ee25fff747b0c8b5a0141dc05fc7b8c0f5908ee81c27ad3ec61f603e13c66fc676033061", } [09-07-02 08:13:23.5074] Slim::Plugin::Pandora::ProtocolHandler::trackGain (362) Using replaygain value of -3.55 for Pandora track [09-07-02 08:17:47.1171] Slim::Plugin::Pandora::ProtocolHandler::getNextTrack (165) Getting next track from SqueezeNetwork for stationid=96201477886713760 [09-07-02 08:17:47.3512] Slim::Plugin::Pandora::ProtocolHandler::gotNextTrack (190) Got Pandora track: { albumArtUrl => "http://images-sjl-4.pandora.com/images/public/amz/0/7/0/9/602498619070_455W_455H.jpg", albumDetailUrl => "http://www.pandora.com/music/album/weezer/weezer+blue+album+deluxe+edition?ad=0:28:1:94061:ip,ip:0", albumName => "Weezer (Blue Album) (Deluxe Edition)", allowFeedback => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"), amazonAlbumAsin => "B0001JXQEM", "amazonAlbumDigitalAsin" => "B000W21ER4", amazonAlbumUrl => "http://www.amazon.com/dp/B000003TAW/?", "amazonSongDigitalAsin" => "B000W23KMQ", artistDetailUrl => "http://www.pandora.com/music/artist/weezer?ad=0:28:1:94061:ip,ip:0", artistName => "Weezer", audioUrl => "http://audio-sjl-4.pandora.com/access/?version=4&lid=72228768&token=X9Y1iEwvM9RxdZtNHwYlZcoPRX1o%2BOWS5VknXPsyzGe%2Fm6mQ4VGrAFCe8uND4LCybdj7fhek1C7xn68dKB4%2F%2F7TXjd4YLlmWGKgZRJXI74gX4C7u%2BqRye%2BE%2F08WOCDwEEhVI2hj1hVsZPDoc0ziwHQcFKe6A4qPIrRES3uQ83CdmXuWpzD1Cj6sF5mCEY7WtscIQbXfL9KmSqObMYa%2FEfnwuhQwYinAKNcz5UMXfNwsScaRBMl%2Frk49246%2B8eJ2NZYzSGGssHgomsi7c%2B8V2DKVEuRQ4ibJigfssGRsdJHC9DwQCS%2BwOe4vw%2B9lZ7vDx", canSkip => 1, itunesSongUrl => "http://click.linksynergy.com/fs-bin/stat?id=FLenzF8lvbI&offerid=78941&type=3&subid=0&tmpid=1826&RD_PARM1=http%253A%252F%252Fphobos.apple.com%252FWebObjects%252FMZStore.woa%252Fwa%252FviewAlbum%253Fi%253D115241%2526id%253D115255%2526partnerId%3D30", secs => 159, songDetailUrl => "http://www.pandora.com/music/song/weezer/buddy+holly?ad=0:28:1:94061:ip,ip:0", songName => "Buddy Holly", songRating => 0, stationId => "96201477886713760", trackGain => "-6.05", trackToken => "72825b9b696ccaa247b0c8b5a0141dc05fc7b8c0f5908ee81c27ad3ec61f603e13c66fc676033061", }
Investigations are proving difficult
I should mention that since I filed the bug, I've caught SC reporting the wrong song a few times. Not all the time, and not reproducibly. Just a few times...
I continue to be unable to reproduce this, or anything similar with other sources. Please can anyone who experiences this, either occassionally or repeatedly, please run with logging enabled at level player.source=info and submit the logfile here, along with a description of what happened and when.
Unable to reproduce. Closing until we see it again.
Ok here's a log of my players currently having this problem. The now playing data is exactly 1 song behind whats actually playing, and its been like this for an hour now. This is with player.source and plugin.pandora logging enabled: [09-08-31 11:26:53.4326] Slim::Player::StreamingController::playerReadyToStream (2005) 00:04:20:26:00:bd [09-08-31 11:26:53.4331] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state IDLE [09-08-31 11:26:53.4338] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state TRACKWAIT [09-08-31 11:26:53.4341] Slim::Player::Song::getNextSong (228) pandora://129088699602182048.mp3 [09-08-31 11:26:53.4346] Slim::Plugin::Pandora::ProtocolHandler::getNextTrack (165) Getting next track from SqueezeNetwork for stationid=129088699602182048 [09-08-31 11:26:53.5392] Slim::Plugin::Pandora::ProtocolHandler::gotNextTrack (190) Got Pandora track: { albumArtUrl => "", albumDetailUrl => "http://www.pandora.com/music/album/fabolous+keri+hilson/everything+everyday+everywhere+radio+single?ad=0:28:1:94061:ip,ip:0", albumName => "Everything, Everyday, Everywhere (Radio Single)", allowFeedback => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"), amazonAlbumUrl => "http://www.amazon.com/gp/search/?index=music&field-artist=Fabolous+%26+Keri+Hilson&field-title=Everything%2C+Everyday%2C+Everywhere+%28Radio+Single%29", artistDetailUrl => "http://www.pandora.com/music/artist/fabolous+keri+hilson?ad=0:28:1:94061:ip,ip:0", artistName => "Fabolous & Keri Hilson", audioUrl => "http://audio-sjl-1.pandora.com/access/3952753632964187467?version=4&lid=72228768&token=FQpahkxNSA3ZE9DuxbS%2FnUgTee94qcSBCh7RBckuzvnDlSV3O2PIAqpCokNWNfIw7Q4tA9n1%2B7KxgVPML9oNqnL0UfPENEIuXBpr82UI2B0cjdPZbwAVCZN9OVGXtl4JCZGVNAp9SmcEdxwJd1dzXAoHieost1jhEhUAqGbeRD2Vw1J5nzYf9vz63%2FCSwCXefGAmLV6v0RCq2%2Fic%2FHy4%2BPmEbiyD2nGb9Hbwm6ck2eJ%2FzmEgfsEjdB8R0Vj59bsbMO6U4rIbJL1EIKxMRVnDIOBVwG7%2BtZmf8hQ7aM7SDP0LSuZIU%2BgLquxm0dwGU24K%2BC%2F9H1qgLG7ihIOueCidLw%3D%3D", canSkip => 1, itunesSongUrl => "http://click.linksynergy.com/fs-bin/stat?id=FLenzF8lvbI&offerid=78941&type=3&subid=0&tmpid=1826&RD_PARM1=http%253A%252F%252Fphobos.apple.com%252FWebObjects%252FMZStore.woa%252Fwa%252FviewAlbum%253Fi%253D324626227%2526id%253D324625850%2526partnerId%3D30", secs => 247, songDetailUrl => "http://www.pandora.com/music/song/fabolous+keri+hilson/everything+everyday+everywhere?ad=0:28:1:94061:ip,ip:0", songName => "Everything, Everyday, Everywhere", songRating => 0, stationId => "129088699602182048", trackToken => "5c2b547487be3ad133fb102cf1c5dd3c6cd4b902ea328a76e5edf82dd3d63af18315373056b25e46b9e7ba7cb904a1b87038435cd2b067a1", } [09-08-31 11:26:53.5398] Slim::Player::StreamingController::_nextTrackReady (725) 00:04:20:26:00:bd: nextTrack will be index 0 [09-08-31 11:26:53.5402] Slim::Player::StreamingController::_Stream (1126) Song queue is now 0,0,0 [09-08-31 11:27:03.5132] Slim::Player::StreamingController::playerStopped (1964) 00:04:20:26:00:bd [09-08-31 11:27:03.5136] Slim::Player::StreamingController::_setPlayingState (2175) new playing state STOPPED [09-08-31 11:27:03.5140] Slim::Player::StreamingController::_Stream (1126) Song queue is now 0,0 [09-08-31 11:27:03.5143] Slim::Player::StreamingController::_Stream (1135) 00:04:20:26:00:bd: preparing to stream song index 0 [09-08-31 11:27:03.5146] Slim::Player::Song::open (357) pandora://129088699602182048.mp3 [09-08-31 11:27:03.5156] Slim::Player::TranscodingHelper::getConvertCommand2 (430) Error: Didn't find any command matches for type: mp3 [09-08-31 11:27:03.5159] Slim::Player::Song::open (377) seek=false time=0 canSeek=0SEEK_ERROR_TYPE_NOT_SUPPORTEDPandora [09-08-31 11:27:03.5166] Slim::Player::TranscodingHelper::getConvertCommand2 (433) Matched: mp3->mp3 via: - [09-08-31 11:27:03.5170] Slim::Player::Song::open (398) Transcoder: streamMode=I, streamformat=mp3 [09-08-31 11:27:03.5174] Slim::Player::Song::open (436) URL supports direct streaming [pandora://129088699602182048.mp3->http://audio-sjl-1.pandora.com/access/3952753632964187467?version=4&lid=72228768&token=FQpahkxNSA3ZE9DuxbS%2FnUgTee94qcSBCh7RBckuzvnDlSV3O2PIAqpCokNWNfIw7Q4tA9n1%2B7KxgVPML9oNqnL0UfPENEIuXBpr82UI2B0cjdPZbwAVCZN9OVGXtl4JCZGVNAp9SmcEdxwJd1dzXAoHieost1jhEhUAqGbeRD2Vw1J5nzYf9vz63%2FCSwCXefGAmLV6v0RCq2%2Fic%2FHy4%2BPmEbiyD2nGb9Hbwm6ck2eJ%2FzmEgfsEjdB8R0Vj59bsbMO6U4rIbJL1EIKxMRVnDIOBVwG7%2BtZmf8hQ7aM7SDP0LSuZIU%2BgLquxm0dwGU24K%2BC%2F9H1qgLG7ihIOueCidLw%3D%3D] [09-08-31 11:27:03.5183] Slim::Player::StreamingController::_Stream (1186) 00:04:20:26:00:bd: stream [09-08-31 11:27:03.5188] Slim::Plugin::Pandora::ProtocolHandler::trackGain (362) Using replaygain value of 0 for Pandora track [09-08-31 11:27:03.5480] Slim::Player::StreamingController::_Stream (1217) Song queue is now 0,0 [09-08-31 11:27:03.5484] Slim::Player::StreamingController::_setPlayingState (2175) new playing state BUFFERING [09-08-31 11:27:03.5487] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state STREAMING [09-08-31 11:27:03.6450] Slim::Player::Player::_buffering (1129) Buffering... 0 / 20480 [09-08-31 11:27:03.7558] Slim::Player::TranscodingHelper::getConvertCommand2 (430) Error: Didn't find any command matches for type: mp3 [09-08-31 11:27:03.9476] Slim::Player::Player::_buffering (1129) Buffering... 0 / 20480 [09-08-31 11:27:04.2504] Slim::Player::Player::_buffering (1129) Buffering... 0 / 20480 [09-08-31 11:27:04.5530] Slim::Player::Player::_buffering (1129) Buffering... 90027 / 20480 [09-08-31 11:27:46.5723] Slim::Player::StreamingController::playerEndOfStream (2084) 00:04:20:26:00:bd [09-08-31 11:27:46.5726] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state STREAMOUT [09-08-31 11:27:46.5732] Slim::Player::StreamingController::_setPlayingState (2175) new playing state PLAYING [09-08-31 11:27:46.5735] Slim::Player::StreamingController::_Playing (361) Song 0 has now started playing [09-08-31 11:27:46.5742] Slim::Player::StreamingController::_Playing (391) Song queue is now 0,0 [09-08-31 11:27:46.8785] Slim::Player::TranscodingHelper::getConvertCommand2 (430) Error: Didn't find any command matches for type: mp3 [09-08-31 11:31:03.1771] Slim::Player::StreamingController::playerReadyToStream (2005) 00:04:20:26:00:bd [09-08-31 11:31:03.1775] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state IDLE [09-08-31 11:31:03.1782] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state TRACKWAIT [09-08-31 11:31:03.1786] Slim::Player::Song::getNextSong (228) pandora://129088699602182048.mp3 [09-08-31 11:31:03.1791] Slim::Plugin::Pandora::ProtocolHandler::getNextTrack (165) Getting next track from SqueezeNetwork for stationid=129088699602182048 [09-08-31 11:31:03.6948] Slim::Plugin::Pandora::ProtocolHandler::gotNextTrack (190) Got Pandora track: { albumArtUrl => "", albumDetailUrl => "http://www.pandora.com/music/album/pitbull/i+know+you+want+me+calle+ocho+radio+single?ad=0:28:1:94061:ip,ip:0", albumName => "I Know You Want Me (Calle Ocho) (Radio Single)", allowFeedback => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"), "amazonAlbumDigitalAsin" => "B001VG2DJS", amazonAlbumUrl => "http://www.amazon.com/gp/search/?index=music&field-artist=Pitbull&field-title=I+Know+You+Want+Me+%28Calle+Ocho%29+%28Radio+Single%29", "amazonSongDigitalAsin" => "B001VFWQEQ", artistDetailUrl => "http://www.pandora.com/music/artist/pitbull?ad=0:28:1:94061:ip,ip:0", artistName => "Pitbull", audioUrl => "http://audio-sjl-t2-1.pandora.com/access/3111309298133984758?version=4&lid=72228768&token=lv4mXHnqTpC%2BrjNGQoPJbr9YhuV2AKH%2FQbi51kpM76ZgF5Iq%2Bu88JGYE%2Ba1B5MSBKqoSsq3PmcCq69Lpe9238txM9%2FQScAUKskR0eFxUhSOJwlqdTDZf62xLrYgFGrm%2FQrHpk%2FTUlYXbNRqLADyspTJfuzt36iUtfxT3tkyxJnjtDNkQi%2FDvrwfXBFae633XwB2%2BN1TNoxQpSSwl7SYCQR1%2BiwSwlbPP%2BD4z2N%2BxU%2FAzTYZdKPu36kSHGRw%2BKY2m%2FZyzwGdTKTG5T2zCuGVWrhg92aruDMYep94uioAhBje%2BaID0PvSOWuTBVwGTbNPJ", canSkip => 1, itunesSongUrl => "http://click.linksynergy.com/fs-bin/stat?id=FLenzF8lvbI&offerid=78941&type=3&subid=0&tmpid=1826&RD_PARM1=http%253A%252F%252Fphobos.apple.com%252FWebObjects%252FMZSearch.woa%252Fwa%252FadvancedSearch%253Fmedia%253Dmusic%2526artistTerm%253DPitbull%2526songTerm%253DI%252BKnow%252BYou%252BWant%252BMe%252B%252528Calle%252BOcho%252529%2526originStoreFront%253D143441%2526partnerId%3D30", secs => 244, songDetailUrl => "http://www.pandora.com/music/song/pitbull/i+know+you+want+me+calle+ocho?ad=0:28:1:94061:ip,ip:0", songName => "I Know You Want Me (Calle Ocho)", songRating => 0, stationId => "129088699602182048", trackGain => "-1.79", trackToken => "cdd422b5853a614e33fb102cf1c5dd3c6cd4b902ea328a76e85d7aa65030053d0063f3fae5b1639f", } [09-08-31 11:31:03.6952] Slim::Player::StreamingController::_nextTrackReady (725) 00:04:20:26:00:bd: nextTrack will be index 0 [09-08-31 11:31:03.6956] Slim::Player::StreamingController::_Stream (1126) Song queue is now 0,0,0
Ok, I see a clue: [09-08-31 11:31:03.6956] Slim::Player::StreamingController::_Stream (1126) Song queue is now 0,0,0 This should not happen - three songs in the queue. I thought that I fixed this in r28228 but I guess not. Perhaps that was a different, if related problem. Do you have a much longer log segment available? Going all the way back to when you pressed play.
I don't but I'll try to get one today starting from the beginning.
Here's a much longer log entry ... I turned on player.source to debug instead of Info this time. Hope this helps. (one thing, this is not showing the problem yet ... but it does show the 0,0 issue that you mentioned). I also cut out most of the player sync check messages.. [09-09-01 07:36:51.0034] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused [09-09-01 07:36:51.0044] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused [09-09-01 07:36:54.3910] Slim::Player::StreamingController::stop (1904) 00:04:20:1e:04:ad [09-09-01 07:36:54.3914] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: Stop in PAUSED-STREAMING -> Slim::Player::StreamingController::_Stop [09-09-01 07:36:54.3930] Slim::Player::StreamingController::_Stop (600) Song queue is now 0 [09-09-01 07:36:54.3935] Slim::Player::SongStreamController::DESTROY (45) DESTROY(Slim::Player::SongStreamController=HASH(0x36e46f0)) live=0 [09-09-01 07:36:54.3938] Slim::Player::StreamingController::_setPlayingState (2175) new playing state STOPPED [09-09-01 07:36:54.3941] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state IDLE [09-09-01 07:36:54.3946] Slim::Player::StreamingController::_eventAction (303) 00:04:20:1e:04:ad: Stop - new state STOPPED-IDLE [09-09-01 07:36:54.3951] Slim::Player::Song::DESTROY (159) DESTROY(Slim::Player::Song=ARRAY(0x3491df8)) live=3: index=0, url=file:///Volumes/Drobo/Music/FLACs/Dr.%20Dre%20-%202001/09%20Light%20Speed.flac [09-09-01 07:36:54.4035] Slim::Player::StreamingController::playerActive (1801) 00:04:20:1e:04:ad player already active: 00:04:20:1e:04:ad [09-09-01 07:36:54.4046] Slim::Player::StreamingController::play (1907) 00:04:20:1e:04:ad [09-09-01 07:36:54.4050] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: Play in STOPPED-IDLE -> Slim::Player::StreamingController::_StopGetNext [09-09-01 07:36:54.4054] Slim::Player::StreamingController::_eventAction (284) params: index => 0 seekdata => undef [09-09-01 07:36:54.4067] Slim::Player::StreamingController::_setPlayingState (2175) new playing state STOPPED [09-09-01 07:36:54.4071] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state IDLE [09-09-01 07:36:54.4078] Slim::Player::Song::new (107) index 0 -> pandora://123360712172904352.mp3 [09-09-01 07:36:54.4088] Slim::Player::Song::new (149) live=4 [09-09-01 07:36:54.4091] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state TRACKWAIT [09-09-01 07:36:54.4095] Slim::Player::Song::getNextSong (228) pandora://123360712172904352.mp3 [09-09-01 07:36:54.4100] Slim::Player::Song::getNextSong (250) scanning URL pandora://123360712172904352.mp3 [09-09-01 07:36:54.4105] Slim::Player::Song::__ANON__ (296) Found a playlist [09-09-01 07:36:54.4109] Slim::Player::Song::getNextSong (228) pandora://123360712172904352.mp3 [09-09-01 07:36:54.4121] Slim::Plugin::Pandora::ProtocolHandler::getNextTrack (165) Getting next track from SqueezeNetwork for stationid=123360712172904352 [09-09-01 07:36:54.4164] Slim::Player::StreamingController::_playersMessage (768) Fetching track details...: pandora://123360712172904352.mp3 [09-09-01 07:36:54.4172] Slim::Player::StreamingController::_eventAction (303) 00:04:20:1e:04:ad: Play - new state STOPPED-TRACKWAIT [09-09-01 07:36:54.7995] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in STOPPED-TRACKWAIT -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:54.8004] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in STOPPED-TRACKWAIT -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:54.8011] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in STOPPED-TRACKWAIT -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:54.8019] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in STOPPED-TRACKWAIT -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:54.8025] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in STOPPED-TRACKWAIT -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:54.8033] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in STOPPED-TRACKWAIT -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:55.1973] Slim::Plugin::Pandora::ProtocolHandler::gotNextTrack (190) Got Pandora track: { albumArtUrl => "http://images-sjl-2.pandora.com/images/public/amz/8/8/3/1/602517891388_500W_495H.jpg", albumDetailUrl => "http://www.pandora.com/music/album/lady+gaga/fame?ad=0:28:1:94061:ip,ip:0", albumName => "The Fame", allowFeedback => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"), amazonAlbumAsin => "B001GM28HO", "amazonAlbumDigitalAsin" => "B001IXSU8M", amazonAlbumUrl => "http://www.amazon.com/dp/B001GM28HO/?", "amazonSongDigitalAsin" => "B001IXOYDC", artistDetailUrl => "http://www.pandora.com/music/artist/lady+gaga?ad=0:28:1:94061:ip,ip:0", artistName => "Lady Gaga", audioUrl => "http://audio-sjl-t2-1.pandora.com/access/181062817191565409?version=4&lid=72228768&token=3FavXwh12HNKRSjTHnpB9uJBMYZvYDI8D3MOVKOxfNiitbWZ9RtDJWb6L2ELh6EBERon93Or3HRUyWy8FHvsoSIuhysFCuTUuOvoA9n6GeJJwwp5%2BioeTf7E%2FENMoV%2BckuMq82GehzTrPMG8eA%2Bn8kUrCWYVU86uqTRye%2FKnbHJovVke9Kq2S46Gsr8fTJELZ3VnXqVHAZn0sKt8prWYdsLgMGFxMci7RgmVj9c3nlmeummgDeUei9Wnast0nWFVxHaYIIN9XDz0s%2FnmwBcmeajD%2B3aWHRGVIpZQuP2ZNlWTqNvGEYer%2FSaTUFpqULW3%2BtPOvyExphg%3D", canSkip => 1, itunesSongUrl => "http://click.linksynergy.com/fs-bin/stat?id=FLenzF8lvbI&offerid=78941&type=3&subid=0&tmpid=1826&RD_PARM1=http%253A%252F%252Fphobos.apple.com%252FWebObjects%252FMZStore.woa%252Fwa%252FviewAlbum%253Fi%253D294084306%2526id%253D294084085%2526partnerId%3D30", secs => 200, songDetailUrl => "http://www.pandora.com/music/song/lady+gaga/boys+boys+boys?ad=0:28:1:94061:ip,ip:0", songName => "Boys Boys Boys", songRating => 0, stationId => "123360712172904352", trackGain => "-5.66", trackToken => "8f4afb1f9ff8c34bff96b52de3f37a14c0eae584306a7a8dec7c1cde44492e4a22924624ee55a4c5", } [09-09-01 07:36:55.1978] Slim::Player::StreamingController::_nextTrackReady (725) 00:04:20:1e:04:ad: nextTrack will be index 0 [09-09-01 07:36:55.1983] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: NextTrackReady in STOPPED-TRACKWAIT -> Slim::Player::StreamingController::_Stream [09-09-01 07:36:55.1988] Slim::Player::StreamingController::_Stream (1126) Song queue is now 0 [09-09-01 07:36:55.1991] Slim::Player::StreamingController::_Stream (1135) 00:04:20:1e:04:ad: preparing to stream song index 0 [09-09-01 07:36:55.1994] Slim::Player::Song::open (357) pandora://123360712172904352.mp3 [09-09-01 07:36:55.2003] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:36:55.2006] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2009] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2013] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-* [09-09-01 07:36:55.2016] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-* [09-09-01 07:36:55.2019] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2022] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2034] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-* [09-09-01 07:36:55.2039] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-* [09-09-01 07:36:55.2043] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2046] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2050] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-* [09-09-01 07:36:55.2053] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-* [09-09-01 07:36:55.2056] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2060] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2063] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-* [09-09-01 07:36:55.2066] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-* [09-09-01 07:36:55.2070] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2074] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2077] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-* [09-09-01 07:36:55.2080] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-* [09-09-01 07:36:55.2083] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2088] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2093] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-* [09-09-01 07:36:55.2097] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-* [09-09-01 07:36:55.2101] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:36:55.2104] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:36:55.2107] Slim::Player::TranscodingHelper::checkBin (242) Found command: - [09-09-01 07:36:55.2110] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting - because no available stream mode supported: R [09-09-01 07:36:55.2113] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-transcode-* [09-09-01 07:36:55.2115] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-transcode-* is enabled [09-09-01 07:36:55.2118] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:36:55.2121] Slim::Player::TranscodingHelper::checkBin (242) Found command: [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - [09-09-01 07:36:55.2124] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - because no available stream mode supported: R [09-09-01 07:36:55.2127] Slim::Player::TranscodingHelper::getConvertCommand2 (430) Error: Didn't find any command matches for type: mp3 [09-09-01 07:36:55.2131] Slim::Player::Song::open (377) seek=false time=0 canSeek=0SEEK_ERROR_TYPE_NOT_SUPPORTEDPandora [09-09-01 07:36:55.2136] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:36:55.2139] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2141] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2144] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-* [09-09-01 07:36:55.2147] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-* [09-09-01 07:36:55.2150] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2153] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2156] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-* [09-09-01 07:36:55.2159] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-* [09-09-01 07:36:55.2161] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2164] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2167] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-* [09-09-01 07:36:55.2170] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-* [09-09-01 07:36:55.2172] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2175] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2178] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-* [09-09-01 07:36:55.2181] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-* [09-09-01 07:36:55.2184] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2186] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2189] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-* [09-09-01 07:36:55.2192] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-* [09-09-01 07:36:55.2195] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.2197] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-00:04:20:1e:04:ad [09-09-01 07:36:55.2200] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-* [09-09-01 07:36:55.2203] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-* [09-09-01 07:36:55.2206] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:36:55.2208] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:36:55.2211] Slim::Player::TranscodingHelper::checkBin (242) Found command: - [09-09-01 07:36:55.2214] Slim::Player::TranscodingHelper::getConvertCommand2 (433) Matched: mp3->mp3 via: - [09-09-01 07:36:55.2217] Slim::Player::Song::open (398) Transcoder: streamMode=I, streamformat=mp3 [09-09-01 07:36:55.2222] Slim::Player::Song::open (436) URL supports direct streaming [pandora://123360712172904352.mp3->http://audio-sjl-t2-1.pandora.com/access/181062817191565409?version=4&lid=72228768&token=3FavXwh12HNKRSjTHnpB9uJBMYZvYDI8D3MOVKOxfNiitbWZ9RtDJWb6L2ELh6EBERon93Or3HRUyWy8FHvsoSIuhysFCuTUuOvoA9n6GeJJwwp5%2BioeTf7E%2FENMoV%2BckuMq82GehzTrPMG8eA%2Bn8kUrCWYVU86uqTRye%2FKnbHJovVke9Kq2S46Gsr8fTJELZ3VnXqVHAZn0sKt8prWYdsLgMGFxMci7RgmVj9c3nlmeummgDeUei9Wnast0nWFVxHaYIIN9XDz0s%2FnmwBcmeajD%2B3aWHRGVIpZQuP2ZNlWTqNvGEYer%2FSaTUFpqULW3%2BtPOvyExphg%3D] [09-09-01 07:36:55.2245] Slim::Player::SongStreamController::new (32) live=1 [09-09-01 07:36:55.2254] Slim::Player::StreamingController::_Stream (1186) 00:04:20:1e:04:ad: stream [09-09-01 07:36:55.2260] Slim::Plugin::Pandora::ProtocolHandler::trackGain (362) Using replaygain value of -5.66 for Pandora track [09-09-01 07:36:55.2279] Slim::Player::Boom::play (335) Setting LineIn to 0 for [http://audio-sjl-t2-1.pandora.com/access/181062817191565409?version=4&lid=72228768&token=3FavXwh12HNKRSjTHnpB9uJBMYZvYDI8D3MOVKOxfNiitbWZ9RtDJWb6L2ELh6EBERon93Or3HRUyWy8FHvsoSIuhysFCuTUuOvoA9n6GeJJwwp5%2BioeTf7E%2FENMoV%2BckuMq82GehzTrPMG8eA%2Bn8kUrCWYVU86uqTRye%2FKnbHJovVke9Kq2S46Gsr8fTJELZ3VnXqVHAZn0sKt8prWYdsLgMGFxMci7RgmVj9c3nlmeummgDeUei9Wnast0nWFVxHaYIIN9XDz0s%2FnmwBcmeajD%2B3aWHRGVIpZQuP2ZNlWTqNvGEYer%2FSaTUFpqULW3%2BtPOvyExphg%3D] [09-09-01 07:36:55.2283] Slim::Player::Boom::setLineIn (427) Switching to line in 0 [09-09-01 07:36:55.2996] Slim::Player::StreamingController::_Stream (1217) Song queue is now 0 [09-09-01 07:36:55.3000] Slim::Player::StreamingController::_setPlayingState (2175) new playing state BUFFERING [09-09-01 07:36:55.3004] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state STREAMING [09-09-01 07:36:55.3007] Slim::Player::StreamingController::_eventAction (303) 00:04:20:1e:04:ad: NextTrackReady - new state BUFFERING-STREAMING [09-09-01 07:36:55.3111] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:36:55.3114] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.3117] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-00:04:20:1e:04:ad [09-09-01 07:36:55.3121] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-* [09-09-01 07:36:55.3124] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-* [09-09-01 07:36:55.3127] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.3130] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-00:04:20:1e:04:ad [09-09-01 07:36:55.3132] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-* [09-09-01 07:36:55.3135] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-* [09-09-01 07:36:55.3138] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.3141] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-00:04:20:1e:04:ad [09-09-01 07:36:55.3144] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-* [09-09-01 07:36:55.3146] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-* [09-09-01 07:36:55.3149] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.3152] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-00:04:20:1e:04:ad [09-09-01 07:36:55.3155] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-* [09-09-01 07:36:55.3157] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-* [09-09-01 07:36:55.3160] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.3163] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-00:04:20:1e:04:ad [09-09-01 07:36:55.3166] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-* [09-09-01 07:36:55.3169] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-* [09-09-01 07:36:55.3185] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.3192] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-00:04:20:1e:04:ad [09-09-01 07:36:55.3195] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-* [09-09-01 07:36:55.3200] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-* [09-09-01 07:36:55.3204] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:36:55.3207] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:36:55.3210] Slim::Player::TranscodingHelper::checkBin (242) Found command: - [09-09-01 07:36:55.3213] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting - because no available stream mode supported: R [09-09-01 07:36:55.3216] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-transcode-* [09-09-01 07:36:55.3219] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-transcode-* is enabled [09-09-01 07:36:55.3222] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:36:55.3225] Slim::Player::TranscodingHelper::checkBin (242) Found command: [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - [09-09-01 07:36:55.3228] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - because no available stream mode supported: R [09-09-01 07:36:55.3231] Slim::Player::TranscodingHelper::getConvertCommand2 (430) Error: Didn't find any command matches for type: mp3 [09-09-01 07:36:55.3271] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in BUFFERING-STREAMING -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:55.3278] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in BUFFERING-STREAMING -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:55.3285] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in BUFFERING-STREAMING -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:55.3556] Slim::Player::Player::_buffering (1129) Buffering... 0 / 20480 [09-09-01 07:36:55.3617] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in BUFFERING-STREAMING -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:55.3625] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in BUFFERING-STREAMING -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:55.4293] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in BUFFERING-STREAMING -> Slim::Player::StreamingController::_NoOp [09-09-01 07:36:55.6204] Slim::Player::StreamingController::playerTrackStarted (1987) 00:04:20:1e:04:ad [09-09-01 07:36:55.6209] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: Started in BUFFERING-STREAMING -> Slim::Player::StreamingController::_Playing [09-09-01 07:36:55.6212] Slim::Player::StreamingController::_setPlayingState (2175) new playing state PLAYING [09-09-01 07:36:55.6215] Slim::Player::StreamingController::_Playing (361) Song 0 has now started playing [09-09-01 07:36:55.6224] Slim::Player::StreamingController::_Playing (391) Song queue is now 0 [09-09-01 07:36:55.6227] Slim::Player::StreamingController::_eventAction (303) 00:04:20:1e:04:ad: Started - new state PLAYING-STREAMING [09-09-01 07:36:55.9311] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:36:55.9315] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.9318] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-00:04:20:1e:04:ad [09-09-01 07:36:55.9322] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-* [09-09-01 07:36:55.9324] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-* [09-09-01 07:36:55.9327] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.9330] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-00:04:20:1e:04:ad [09-09-01 07:36:55.9333] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-* [09-09-01 07:36:55.9336] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-* [09-09-01 07:36:55.9338] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.9341] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-00:04:20:1e:04:ad [09-09-01 07:36:55.9345] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-* [09-09-01 07:36:55.9349] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-* [09-09-01 07:36:55.9356] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.9360] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-00:04:20:1e:04:ad [09-09-01 07:36:55.9362] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-* [09-09-01 07:36:55.9366] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-* [09-09-01 07:36:55.9369] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.9372] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-00:04:20:1e:04:ad [09-09-01 07:36:55.9375] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-* [09-09-01 07:36:55.9378] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-* [09-09-01 07:36:55.9382] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-00:04:20:1e:04:ad [09-09-01 07:36:55.9385] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-00:04:20:1e:04:ad [09-09-01 07:36:55.9388] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-* [09-09-01 07:36:55.9390] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-* [09-09-01 07:36:55.9393] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:36:55.9396] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:36:55.9399] Slim::Player::TranscodingHelper::checkBin (242) Found command: - [09-09-01 07:36:55.9402] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting - because no available stream mode supported: R [09-09-01 07:36:55.9405] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-transcode-* [09-09-01 07:36:55.9407] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-transcode-* is enabled [09-09-01 07:36:55.9410] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:36:55.9413] Slim::Player::TranscodingHelper::checkBin (242) Found command: [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - [09-09-01 07:36:55.9416] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - because no available stream mode supported: R [09-09-01 07:36:55.9419] Slim::Player::TranscodingHelper::getConvertCommand2 (430) Error: Didn't find any command matches for type: mp3 [09-09-01 07:37:03.7372] Slim::Player::StreamingController::playerEndOfStream (2084) 00:04:20:1e:04:ad [09-09-01 07:37:03.7376] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: EndOfStream in PLAYING-STREAMING -> Slim::Player::StreamingController::_AutoStart [09-09-01 07:37:03.7380] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state STREAMOUT [09-09-01 07:40:06.5079] Slim::Player::StreamingController::playerReadyToStream (2005) 00:04:20:1e:04:ad [09-09-01 07:40:06.5084] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: ReadyToStream in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_RetryOrNext [09-09-01 07:40:06.5087] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state IDLE [09-09-01 07:40:06.5095] Slim::Player::Song::clonePlaylistSong (181) live=5 [09-09-01 07:40:06.5098] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state TRACKWAIT [09-09-01 07:40:06.5102] Slim::Player::Song::getNextSong (228) pandora://123360712172904352.mp3 [09-09-01 07:40:06.5108] Slim::Plugin::Pandora::ProtocolHandler::getNextTrack (165) Getting next track from SqueezeNetwork for stationid=123360712172904352 [09-09-01 07:40:06.5136] Slim::Player::StreamingController::_eventAction (303) 00:04:20:1e:04:ad: ReadyToStream - new state PLAYING-TRACKWAIT [09-09-01 07:40:06.9409] Slim::Plugin::Pandora::ProtocolHandler::gotNextTrack (190) Got Pandora track: { albumArtUrl => "http://images-sjl-3.pandora.com/images/public/amz/3/2/3/2/886970402323_500W_500H.jpg", albumDetailUrl => "http://www.pandora.com/music/album/kat+deluna/9+lives?ad=0:28:1:94061:ip,ip:0", albumName => "9 Lives", allowFeedback => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"), amazonAlbumAsin => "B000S2B25M", "amazonAlbumDigitalAsin" => "B00138KGDY", amazonAlbumUrl => "http://www.amazon.com/gp/search/?index=music&field-artist=Kat+Deluna&field-title=Whine+Up", "amazonSongDigitalAsin" => "B0013832QW", artistDetailUrl => "http://www.pandora.com/music/artist/kat+deluna?ad=0:28:1:94061:ip,ip:0", artistName => "Kat Deluna", audioUrl => "http://audio-sjl-t2-1.pandora.com/access/1049844491288589078?version=4&lid=72228768&token=7vxZIBjA2AbnNoH2V6gfkmlr08QNZD%2F%2Be9aIHCj1mk7%2FPLMnu%2BvY9we%2FUHVhqC9w4R6GLfYKjZODF%2F0eEm%2BMsiPKxsm0ftr6rNOG9YEMn5ShKTemDC3lRmYQfqGXsjlLKkML%2Bg30wxK5F4wPtc4NwGwQQJKAnCkT%2Fyw93VPGYIsvW3%2BjHNBgRvRObkc6N25QrO8txe36ShXFVVVdy0a%2F2ni%2FckBFKW%2FG6J%2B5x8zLmyh7%2Fzlj68XnT%2FKRaTSUAmcqrfeShcUGQJNDX6ouY9YOXGC7nrc%2FOXOp7YKgCc86y2cjmaaMHy7Azq7hHOrzlcKu", canSkip => 1, itunesSongUrl => "http://click.linksynergy.com/fs-bin/stat?id=FLenzF8lvbI&offerid=78941&type=3&subid=0&tmpid=1826&RD_PARM1=http%253A%252F%252Fphobos.apple.com%252FWebObjects%252FMZStore.woa%252Fwa%252FviewAlbum%253Fi%253D254586525%2526id%253D254586487%2526partnerId%3D30", secs => 203, songDetailUrl => "http://www.pandora.com/music/song/kat+deluna/whine+up?ad=0:28:1:94061:ip,ip:0", songName => "Whine Up", songRating => 0, stationId => "123360712172904352", trackGain => "-4.57", trackToken => "a5ac5f9361b3802931fb416d9e173896e49270a776aa1c12c1677f5ff97fb490d9b3a00e50e845e0", } [09-09-01 07:40:06.9413] Slim::Player::StreamingController::_nextTrackReady (725) 00:04:20:1e:04:ad: nextTrack will be index 0 [09-09-01 07:40:06.9417] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: NextTrackReady in PLAYING-TRACKWAIT -> Slim::Player::StreamingController::_StreamIfReady [09-09-01 07:40:06.9422] Slim::Player::StreamingController::_Stream (1126) Song queue is now 0,0 [09-09-01 07:40:06.9425] Slim::Player::StreamingController::_Stream (1135) 00:04:20:1e:04:ad: preparing to stream song index 0 [09-09-01 07:40:06.9429] Slim::Player::Song::open (357) pandora://123360712172904352.mp3 [09-09-01 07:40:06.9438] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:40:06.9442] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9445] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9448] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-* [09-09-01 07:40:06.9451] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-* [09-09-01 07:40:06.9454] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9457] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9459] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-* [09-09-01 07:40:06.9463] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-* [09-09-01 07:40:06.9466] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9469] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9472] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-* [09-09-01 07:40:06.9474] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-* [09-09-01 07:40:06.9478] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9480] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9483] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-* [09-09-01 07:40:06.9486] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-* [09-09-01 07:40:06.9489] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9492] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9495] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-* [09-09-01 07:40:06.9498] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-* [09-09-01 07:40:06.9500] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9503] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9506] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-* [09-09-01 07:40:06.9509] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-* [09-09-01 07:40:06.9512] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:40:06.9515] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:40:06.9518] Slim::Player::TranscodingHelper::checkBin (242) Found command: - [09-09-01 07:40:06.9521] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting - because no available stream mode supported: R [09-09-01 07:40:06.9524] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-transcode-* [09-09-01 07:40:06.9526] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-transcode-* is enabled [09-09-01 07:40:06.9529] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:40:06.9532] Slim::Player::TranscodingHelper::checkBin (242) Found command: [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - [09-09-01 07:40:06.9536] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - because no available stream mode supported: R [09-09-01 07:40:06.9540] Slim::Player::TranscodingHelper::getConvertCommand2 (430) Error: Didn't find any command matches for type: mp3 [09-09-01 07:40:06.9544] Slim::Player::Song::open (377) seek=false time=0 canSeek=0SEEK_ERROR_TYPE_NOT_SUPPORTEDPandora [09-09-01 07:40:06.9548] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:40:06.9551] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9554] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9557] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-* [09-09-01 07:40:06.9560] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-* [09-09-01 07:40:06.9563] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9566] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9569] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-* [09-09-01 07:40:06.9572] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-* [09-09-01 07:40:06.9575] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9578] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9581] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-* [09-09-01 07:40:06.9584] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-* [09-09-01 07:40:06.9587] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9590] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9593] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-* [09-09-01 07:40:06.9596] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-* [09-09-01 07:40:06.9599] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9601] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9604] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-* [09-09-01 07:40:06.9607] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-* [09-09-01 07:40:06.9611] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-00:04:20:1e:04:ad [09-09-01 07:40:06.9614] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-00:04:20:1e:04:ad [09-09-01 07:40:06.9617] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-* [09-09-01 07:40:06.9620] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-* [09-09-01 07:40:06.9623] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:40:06.9627] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:40:06.9630] Slim::Player::TranscodingHelper::checkBin (242) Found command: - [09-09-01 07:40:06.9633] Slim::Player::TranscodingHelper::getConvertCommand2 (433) Matched: mp3->mp3 via: - [09-09-01 07:40:06.9640] Slim::Player::Song::open (398) Transcoder: streamMode=I, streamformat=mp3 [09-09-01 07:40:06.9647] Slim::Player::Song::open (436) URL supports direct streaming [pandora://123360712172904352.mp3->http://audio-sjl-t2-1.pandora.com/access/1049844491288589078?version=4&lid=72228768&token=7vxZIBjA2AbnNoH2V6gfkmlr08QNZD%2F%2Be9aIHCj1mk7%2FPLMnu%2BvY9we%2FUHVhqC9w4R6GLfYKjZODF%2F0eEm%2BMsiPKxsm0ftr6rNOG9YEMn5ShKTemDC3lRmYQfqGXsjlLKkML%2Bg30wxK5F4wPtc4NwGwQQJKAnCkT%2Fyw93VPGYIsvW3%2BjHNBgRvRObkc6N25QrO8txe36ShXFVVVdy0a%2F2ni%2FckBFKW%2FG6J%2B5x8zLmyh7%2Fzlj68XnT%2FKRaTSUAmcqrfeShcUGQJNDX6ouY9YOXGC7nrc%2FOXOp7YKgCc86y2cjmaaMHy7Azq7hHOrzlcKu] [09-09-01 07:40:06.9651] Slim::Player::SongStreamController::new (32) live=2 [09-09-01 07:40:06.9658] Slim::Player::SongStreamController::DESTROY (45) DESTROY(Slim::Player::SongStreamController=HASH(0x36778e8)) live=1 [09-09-01 07:40:06.9661] Slim::Player::StreamingController::_Stream (1186) 00:04:20:1e:04:ad: stream [09-09-01 07:40:06.9666] Slim::Plugin::Pandora::ProtocolHandler::trackGain (362) Using replaygain value of -4.57 for Pandora track [09-09-01 07:40:06.9681] Slim::Player::Boom::play (335) Setting LineIn to 0 for [http://audio-sjl-t2-1.pandora.com/access/1049844491288589078?version=4&lid=72228768&token=7vxZIBjA2AbnNoH2V6gfkmlr08QNZD%2F%2Be9aIHCj1mk7%2FPLMnu%2BvY9we%2FUHVhqC9w4R6GLfYKjZODF%2F0eEm%2BMsiPKxsm0ftr6rNOG9YEMn5ShKTemDC3lRmYQfqGXsjlLKkML%2Bg30wxK5F4wPtc4NwGwQQJKAnCkT%2Fyw93VPGYIsvW3%2BjHNBgRvRObkc6N25QrO8txe36ShXFVVVdy0a%2F2ni%2FckBFKW%2FG6J%2B5x8zLmyh7%2Fzlj68XnT%2FKRaTSUAmcqrfeShcUGQJNDX6ouY9YOXGC7nrc%2FOXOp7YKgCc86y2cjmaaMHy7Azq7hHOrzlcKu] [09-09-01 07:40:06.9685] Slim::Player::Boom::setLineIn (427) Switching to line in 0 [09-09-01 07:40:06.9805] Slim::Player::StreamingController::_Stream (1217) Song queue is now 0,0 [09-09-01 07:40:06.9809] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state STREAMING [09-09-01 07:40:06.9812] Slim::Player::StreamingController::_eventAction (303) 00:04:20:1e:04:ad: NextTrackReady - new state PLAYING-STREAMING [09-09-01 07:40:06.9875] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:06.9883] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:07.0287] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:08.0057] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:08.0280] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:08.0570] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:08.3824] Slim::Player::StreamingController::playerTrackStarted (1987) 00:04:20:1e:04:ad [09-09-01 07:40:08.3827] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: Started in PLAYING-STREAMING -> Slim::Player::StreamingController::_Playing [09-09-01 07:40:08.3831] Slim::Player::StreamingController::_setPlayingState (2175) new playing state PLAYING [09-09-01 07:40:08.3834] Slim::Player::StreamingController::_Playing (355) Song 0 is not longer in the queue [09-09-01 07:40:08.3837] Slim::Player::Song::DESTROY (159) DESTROY(Slim::Player::Song=ARRAY(0x37e4ac8)) live=4: index=0, url=pandora://123360712172904352.mp3 [09-09-01 07:40:08.3841] Slim::Player::StreamingController::_Playing (361) Song 0 has now started playing [09-09-01 07:40:08.3849] Slim::Player::StreamingController::_Playing (391) Song queue is now 0 [09-09-01 07:40:08.6914] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:40:08.6919] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-00:04:20:1e:04:ad [09-09-01 07:40:08.6922] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-00:04:20:1e:04:ad [09-09-01 07:40:08.6925] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-boom-* [09-09-01 07:40:08.6929] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-wma-*-* [09-09-01 07:40:08.6932] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-00:04:20:1e:04:ad [09-09-01 07:40:08.6935] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-00:04:20:1e:04:ad [09-09-01 07:40:08.6938] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-boom-* [09-09-01 07:40:08.6941] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-ogg-*-* [09-09-01 07:40:08.6946] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-00:04:20:1e:04:ad [09-09-01 07:40:08.6949] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-00:04:20:1e:04:ad [09-09-01 07:40:08.6954] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-boom-* [09-09-01 07:40:08.6956] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-flc-*-* [09-09-01 07:40:08.6960] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-00:04:20:1e:04:ad [09-09-01 07:40:08.6963] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-00:04:20:1e:04:ad [09-09-01 07:40:08.6966] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-boom-* [09-09-01 07:40:08.6968] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-aif-*-* [09-09-01 07:40:08.6971] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-00:04:20:1e:04:ad [09-09-01 07:40:08.6974] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-00:04:20:1e:04:ad [09-09-01 07:40:08.6977] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-boom-* [09-09-01 07:40:08.6980] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-pcm-*-* [09-09-01 07:40:08.6983] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-00:04:20:1e:04:ad [09-09-01 07:40:08.6985] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-00:04:20:1e:04:ad [09-09-01 07:40:08.6988] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-boom-* [09-09-01 07:40:08.6991] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-*-* [09-09-01 07:40:08.6994] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-*-* is enabled [09-09-01 07:40:08.6997] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:40:08.6999] Slim::Player::TranscodingHelper::checkBin (242) Found command: - [09-09-01 07:40:08.7002] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting - because no available stream mode supported: R [09-09-01 07:40:08.7005] Slim::Player::TranscodingHelper::checkBin (232) Checking formats for: mp3-mp3-transcode-* [09-09-01 07:40:08.7008] Slim::Player::TranscodingHelper::enabledFormat (199) Checking to see if mp3-mp3-transcode-* is enabled [09-09-01 07:40:08.7011] Slim::Player::TranscodingHelper::checkBin (240) enabled [09-09-01 07:40:08.7013] Slim::Player::TranscodingHelper::checkBin (242) Found command: [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - [09-09-01 07:40:08.7016] Slim::Player::TranscodingHelper::getConvertCommand2 (366) Rejecting [lame] --silent -q $QUALITY$ -v $BITRATE$ $RESAMPLE$ --mp3input $FILE$ - because no available stream mode supported: R [09-09-01 07:40:08.7019] Slim::Player::TranscodingHelper::getConvertCommand2 (430) Error: Didn't find any command matches for type: mp3 [09-09-01 07:40:09.0345] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:10.0287] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:11.0040] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:11.0049] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:11.0277] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:12.0279] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:13.0288] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:14.0296] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:15.0281] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:15.7856] Slim::Player::StreamingController::playerEndOfStream (2084) 00:04:20:1e:04:ad [09-09-01 07:40:15.7860] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: EndOfStream in PLAYING-STREAMING -> Slim::Player::StreamingController::_AutoStart [09-09-01 07:40:15.7864] Slim::Player::StreamingController::_setStreamingState (2188) new streaming state STREAMOUT [09-09-01 07:40:15.7867] Slim::Player::StreamingController::_eventAction (303) 00:04:20:1e:04:ad: EndOfStream - new state PLAYING-STREAMOUT [09-09-01 07:40:16.0112] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:16.0123] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:16.0298] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:17.0280] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:18.0279] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:19.0281] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:20.0280] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:21.0077] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:21.0088] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:21.0279] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:22.0279] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:23.0281] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:24.0281] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:25.0280] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:26.0040] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:26.0047] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:26.0279] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:27.0279] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:28.0280] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:29.0281] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:30.0280] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:31.0104] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:31.0115] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:31.0292] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:32.0279] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:33.0296] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:34.0280] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:35.0282] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:36.0039] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:36.0049] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [09-09-01 07:40:36.0278] Slim::Player::StreamingController::_eventAction (271) 00:04:20:1e:04:ad: StatusHeartbeat in PLAYING-STREAMOUT -> Slim::Player::StreamingController::_CheckSync [
Debug level will not help. You can go back to info level. The problem is not 0,0 in the song queue - that is normal playing a service such as Pandora. The problem is first obvious when you get 0,0,0, but the cause will actually have been earlier. It would be nicer if you added the logs as attachments rather than pasting the details into a comment where it gets line-wrapped.
== Auto-comment from SVN commit #28561 to the slim repo by ayoung == == https://svn.slimdevices.com/slim?view=revision&revision=28561 == bug 12653: Pandora Streams playing one song while SC reports another... Audit and cleanup manipulation of songqueue (part 1): - Add S::P::StreamingController::resetSongqueue() to replace update-semantic calls to S::P::Source::streamingSongIndex() Clean-up obsolete or little-used helper methods in S::P::Source: - playingSong(), playingSongDuration(), noMoreValidTracks().
== Auto-comment from SVN commit #28562 to the slim repo by ayoung == == https://svn.slimdevices.com/slim?view=revision&revision=28562 == bug 12653: Pandora Streams playing one song while SC reports another... fix typo
== Auto-comment from SVN commit #28565 to the slim repo by ayoung == == https://svn.slimdevices.com/slim?view=revision&revision=28565 == bug 12653: Pandora Streams playing one song while SC reports another... Tighten up the logic associated with adding a Song to the songqueue and making sure that songs which were tentatively added are appropriately flagged so that they can be removed again.
I have not been able to reproduce the problem. I have examined all the songqueue manipulation that goes on and was able to develop a theory that would allow for the queue to be one off with respect to what was playing and what was at the head of the songqueue (the playingSong position). I have been unable to provoke those conditions artificially. I am going to mark this fixed (again) for now. I would not be totally surprised to see it repopened again (although I would be disheartened).
This bug has been marked as fixed in the 7.4.0 release version of SqueezeBox Server! * SqueezeCenter: 28672 * Squeezebox 2 and 3: 130 * Transporter: 80 * Receiver: 65 * Boom: 50 * Controller: 7790 * Radio: 7790 Please see the Release Notes for all the details: http://wiki.slimdevices.com/index.php/Release_Notes If you haven't already, please download and install the new version from http://www.logitechsqueezebox.com/support/download-squeezebox-server.html If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.