-- Logs begin at Thu 2019-02-14 03:11:59 MST, end at Sat 2024-08-17 11:19:49 MST. -- Aug 17 11:18:00 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:18:00 volumio volumio[1020]: info: CorePlayQueue::getTrack 0 Aug 17 11:18:00 volumio volumio[1020]: info: [1723918680055] ControllerPandora::ExpireOldTracks::reaper Aug 17 11:18:00 volumio volumio[1020]: info: [1723918680055] [Pandora] ExpireOldTracks::reaper: No victims found: Expiring zero tracks. Don't worry -- Jason will return. Aug 17 11:18:37 volumio volumio[1020]: info: CorePlayQueue::getTrack 0 Aug 17 11:18:37 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:37 volumio volumio[1020]: info: Prefetching next song Aug 17 11:18:37 volumio volumio[1020]: info: [1723918717457] ControllerSpotify::prefetch Aug 17 11:18:37 volumio volumio[1020]: info: Sending Spotify command with payload to local API: /player/add_to_queue Aug 17 11:18:37 volumio go-librespot[6792]: time="2024-08-17T11:18:37-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 11:18:37 volumio go-librespot[6792]: time="2024-08-17T11:18:37-07:00" level=debug msg="prefetching next track" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:37 volumio go-librespot[6792]: time="2024-08-17T11:18:37-07:00" level=debug msg="selected format OGG_VORBIS_320 (d8367f2e81e55aceddecdb6e83b050078cf092a6)" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:37 volumio go-librespot[6792]: time="2024-08-17T11:18:37-07:00" level=debug msg="requested aes key for file d8367f2e81e55aceddecdb6e83b050078cf092a6, gid: 3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:38 volumio go-librespot[6792]: time="2024-08-17T11:18:38-07:00" level=debug msg="fetched first chunk of 11, total size is 5285907 bytes" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:38 volumio go-librespot[6792]: time="2024-08-17T11:18:38-07:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:38 volumio go-librespot[6792]: time="2024-08-17T11:18:38-07:00" level=info msg="prefetched track \"Call Me\" (duration: 138000ms)" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:38 volumio go-librespot[6792]: time="2024-08-17T11:18:38-07:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:38 volumio go-librespot[6792]: time="2024-08-17T11:18:38-07:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:38 volumio go-librespot[6792]: time="2024-08-17T11:18:38-07:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=trace msg="emitting websocket event: not_playing" Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:7F9E8G4iLUz3eJ1kZrdqZ3","play_origin":"go-librespot"}} Aug 17 11:18:41 volumio volumio[1020]: error: Failed to decode event: not_playing Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:7F9E8G4iLUz3eJ1kZrdqZ3","play_origin":"go-librespot"}} Aug 17 11:18:41 volumio volumio[1020]: error: Failed to decode event: not_playing Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=trace msg="emitting websocket event: will_play" Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","play_origin":"go-librespot"}} Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","play_origin":"go-librespot"}} Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=info msg="loaded track \"Call Me\" (paused: false, position: 0ms, duration: 138000ms, prefetched: true)" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=trace msg="scheduling prefetch in 108s" Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=trace msg="emitting websocket event: metadata" Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","name":"Call Me","artist_names":["ELIA"],"album_name":"Call Me","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","position":0,"duration":138000,"release_date":"year:2024 month:8 day:9","track_number":1,"disc_number":1}} Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","name":"Call Me","artist_names":["ELIA"],"album_name":"Call Me","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","position":0,"duration":138000,"release_date":"year:2024 month:8 day:9","track_number":1,"disc_number":1}} Aug 17 11:18:41 volumio volumio[1020]: info: CoreStateMachine::startPlaybackTimer Aug 17 11:18:41 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 11:18:41 volumio go-librespot[6792]: time="2024-08-17T11:18:41-07:00" level=trace msg="emitting websocket event: playing" Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","play_origin":"go-librespot"}} Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: PUSH STATE SPOTIFY Aug 17 11:18:41 volumio volumio[1020]: SPOTIFY: {"status":"play","service":"spop","title":"Call Me","artist":"ELIA","album":"Call Me","albumart":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","trackType":"spotify","seek":0,"duration":138,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 17 11:18:41 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:18:41 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:41 volumio volumio[1020]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Call Me","artist":"ELIA","album":"Call Me","albumart":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","trackType":"spotify","seek":0,"duration":138,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 17 11:18:41 volumio volumio[1020]: verbose: CURRENT POSITION 1 Aug 17 11:18:41 volumio volumio[1020]: info: CoreStateMachine::syncState stateService play Aug 17 11:18:41 volumio volumio[1020]: info: CoreStateMachine::syncState currentStatus play Aug 17 11:18:41 volumio volumio[1020]: info: Received an update from plugin. extracting info from payload Aug 17 11:18:41 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:41 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:41 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 17 11:18:41 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:41 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:41 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:41 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","play_origin":"go-librespot"}} Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: PUSH STATE SPOTIFY Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: {"status":"play","service":"spop","title":"Call Me","artist":"ELIA","album":"Call Me","albumart":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","trackType":"spotify","seek":0,"duration":138,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Call Me","artist":"ELIA","album":"Call Me","albumart":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","trackType":"spotify","seek":0,"duration":138,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 17 11:18:42 volumio volumio[1020]: verbose: CURRENT POSITION 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::syncState stateService play Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::syncState currentStatus play Aug 17 11:18:42 volumio volumio[1020]: info: Received an update from plugin. extracting info from payload Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: PUSH STATE SPOTIFY Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: {"status":"play","service":"spop","title":"Call Me","artist":"ELIA","album":"Call Me","albumart":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","trackType":"spotify","seek":0,"duration":138,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Call Me","artist":"ELIA","album":"Call Me","albumart":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","trackType":"spotify","seek":0,"duration":138,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 17 11:18:42 volumio volumio[1020]: verbose: CURRENT POSITION 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::syncState stateService play Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::syncState currentStatus play Aug 17 11:18:42 volumio volumio[1020]: info: Received an update from plugin. extracting info from payload Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: PUSH STATE SPOTIFY Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: {"status":"play","service":"spop","title":"Call Me","artist":"ELIA","album":"Call Me","albumart":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","trackType":"spotify","seek":0,"duration":138,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Call Me","artist":"ELIA","album":"Call Me","albumart":"https://i.scdn.co/image/ab67616d00001e0233fddebffe53f3f38ae8bc28","uri":"spotify:track:3Xxvk3YPB4EfL2pdhrIwha","trackType":"spotify","seek":0,"duration":138,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 17 11:18:42 volumio volumio[1020]: verbose: CURRENT POSITION 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::syncState stateService play Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::syncState currentStatus play Aug 17 11:18:42 volumio volumio[1020]: info: Received an update from plugin. extracting info from payload Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:42 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:18:42 volumio volumio[1020]: info: CorePlayQueue::getTrack 1 Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 17 11:18:42 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:18:42 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:18:55 volumio go-librespot[6792]: time="2024-08-17T11:18:55-07:00" level=debug msg="fetched chunk 4/10, size: 524288" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:19:08 volumio volumio[1020]: info: Preload queue cleared Aug 17 11:19:09 volumio go-librespot[6792]: time="2024-08-17T11:19:09-07:00" level=debug msg="fetched chunk 5/10, size: 524288" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:19:13 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: pandora , handleBrowseUri Aug 17 11:19:13 volumio volumio[1020]: info: [1723918753143] ControllerPandora::handleBrowseUri Aug 17 11:19:13 volumio volumio[1020]: info: [1723918753143] ControllerPandora::checkForExpiredStations Aug 17 11:19:13 volumio volumio[1020]: info: [1723918753143] [Pandora] checkForExpiredStations: Stations expired Aug 17 11:19:13 volumio volumio[1020]: info: [1723918753143] ControllerPandora::PandoraHandler::fillStationData Aug 17 11:19:13 volumio volumio[1020]: info: Preload queue cleared Aug 17 11:19:16 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: pandora , handleBrowseUri Aug 17 11:19:16 volumio volumio[1020]: info: [1723918756488] ControllerPandora::handleBrowseUri Aug 17 11:19:16 volumio volumio[1020]: info: [1723918756489] ControllerPandora::checkForExpiredStations Aug 17 11:19:16 volumio volumio[1020]: info: Preload queue cleared Aug 17 11:19:22 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: pandora , handleBrowseUri Aug 17 11:19:22 volumio volumio[1020]: info: [1723918762532] ControllerPandora::handleBrowseUri Aug 17 11:19:22 volumio volumio[1020]: info: [1723918762532] ControllerPandora::checkForExpiredStations Aug 17 11:19:22 volumio volumio[1020]: info: [1723918762533] ControllerPandora::PandoraHandler::fillStationData Aug 17 11:19:22 volumio volumio[1020]: info: [1723918762877] ControllerPandora::PandoraHandler::fetchTracks::fetchStationPlaylist Aug 17 11:19:23 volumio go-librespot[6792]: time="2024-08-17T11:19:23-07:00" level=debug msg="fetched chunk 6/10, size: 524288" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763395] [Pandora] PandoraHandler::fetchTracks::fetchStationPlaylist: Retrieved Leo (Leo Moracchioli) Radio playlist Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763396] ControllerPandora::PandoraHandler::fetchTracks::fillNewTracks Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763397] [Pandora] PandoraHandler::fetchTracks::fillNewTracks: Fetched 4 track(s) Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::addQueueItems Aug 17 11:19:23 volumio volumio[1020]: info: Preload queue cleared Aug 17 11:19:23 volumio volumio[1020]: info: Adding Item to queue: /pandora/stationToken=4565853786759679812trackId=2903035133559225830 Aug 17 11:19:23 volumio volumio[1020]: info: Exploding uri /pandora/stationToken=4565853786759679812trackId=2903035133559225830 in service pandora Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763398] ControllerPandora::explodeUri Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: Adding Item to queue: /pandora/stationToken=4565853786759679812trackId=5597653268079022030 Aug 17 11:19:23 volumio volumio[1020]: info: Exploding uri /pandora/stationToken=4565853786759679812trackId=5597653268079022030 in service pandora Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763399] ControllerPandora::explodeUri Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: Adding Item to queue: /pandora/stationToken=4565853786759679812trackId=7237489684588765161 Aug 17 11:19:23 volumio volumio[1020]: info: Exploding uri /pandora/stationToken=4565853786759679812trackId=7237489684588765161 in service pandora Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763399] ControllerPandora::explodeUri Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: Adding Item to queue: /pandora/stationToken=4565853786759679812trackId=501522624762474516 Aug 17 11:19:23 volumio volumio[1020]: info: Exploding uri /pandora/stationToken=4565853786759679812trackId=501522624762474516 in service pandora Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763399] ControllerPandora::explodeUri Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::volumioPushQueue Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::saveQueue Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::updateTrackBlock Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrackBlock Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::play index 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::stop Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::stPlaybackTimer Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::updateTrackBlock Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrackBlock Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::serviceStop Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::serviceStop Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763453] ControllerPandora::stop Aug 17 11:19:23 volumio volumio[1020]: info: ControllerMpd::stop Aug 17 11:19:23 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand stop Aug 17 11:19:23 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:19:23 volumio volumio[1020]: info: sendMpdCommand stop took 117 milliseconds Aug 17 11:19:23 volumio volumio[1020]: info: ControllerMpd::clear Aug 17 11:19:23 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand clear Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: sendMpdCommand clear took 15 milliseconds Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763586] ControllerPandora::pushState Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: verbose: STATE SERVICE {"service":"pandora","type":"song","trackType":"mp3","title":"In Bloom","name":"In Bloom","artist":"Nirvana","album":"Nevermind (Remastered)","albumart":"http://mediaserver-cont-dc6-2-v4v6.pandora.com/images/1a/bb/b3/f3/e01d4d85a9a7f713dbf648c9/1080W_1080H.jpg","realUri":"http://t1-5.p-cdn.us/access/5891413349222721916.mp3?version=5&lid=3067716&token=ZgIeUI8l9U%2FeZrTUvEQiPHohmpchKFUVtFc8L37oJjoGA6Wd%2F%2FyjjIofAuFUVT0dUPbsxdb09Jn7HXheij2u99eS5ggmn7rk%2BSsPqBNVCbKlp8ZHLM8UG7lopV7MZVXCGVd7fbhuYUgwu2iC%2Fj9bNskW3ZERQ6bTwFz6cVUJDiU1TNtibu78WVZOBLpwkpjuMkIxLVhY%2BE6Bsjlp4mZgbP4dIfYMwlKThMEDgSypVz6o80x7HxRK8DapNNFEINfVaqoa3PYygRknLgvmC2QHT2I2jaTIvHj23hzS0nMA0Vdpt8YLy6XjD1vsu6EbM6R%2BPPLSTkD%2BBe7elGcH%2FQLB0g%3D%3D","isStreaming":true,"duration":255,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"uri":"http://t1-5.p-cdn.us/access/5891413349222721916.mp3?version=5&lid=3067716&token=ZgIeUI8l9U%2FeZrTUvEQiPHohmpchKFUVtFc8L37oJjoGA6Wd%2F%2FyjjIofAuFUVT0dUPbsxdb09Jn7HXheij2u99eS5ggmn7rk%2BSsPqBNVCbKlp8ZHLM8UG7lopV7MZVXCGVd7fbhuYUgwu2iC%2Fj9bNskW3ZERQ6bTwFz6cVUJDiU1TNtibu78WVZOBLpwkpjuMkIxLVhY%2BE6Bsjlp4mZgbP4dIfYMwlKThMEDgSypVz6o80x7HxRK8DapNNFEINfVaqoa3PYygRknLgvmC2QHT2I2jaTIvHj23hzS0nMA0Vdpt8YLy6XjD1vsu6EbM6R%2BPPLSTkD%2BBe7elGcH%2FQLB0g%3D%3D","seek":0,"status":"stop"} Aug 17 11:19:23 volumio volumio[1020]: verbose: CURRENT POSITION 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::syncState stateService stop Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::syncState currentStatus stop Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:19:23 volumio volumio[1020]: info: No code Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::setConsumeUpdateService pandora Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::play index undefined Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::startPlaybackTimer Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763613] ControllerPandora::clearAddPlayTrack Aug 17 11:19:23 volumio volumio[1020]: info: ControllerMpd::clear Aug 17 11:19:23 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand clear Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: touch_display: Setting screensaver timeout to 120 seconds. Aug 17 11:19:23 volumio volumio[1020]: info: touch_display: Setting screensaver timeout to 120 seconds. Aug 17 11:19:23 volumio volumio[1020]: error: updateQueue error: null Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: error: updateQueue error: null Aug 17 11:19:23 volumio volumio[1020]: error: updateQueue error: null Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 52ms Aug 17 11:19:23 volumio volumio[1020]: info: sendMpdCommand clear took 23 milliseconds Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 13ms Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 11ms Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763638] ControllerPandora::checkForExpiredStations Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763639] ControllerPandora::removeTrack Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763639] [Pandora] removeTrack: Not removing track with uri: null at queue index: -1 Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763640] ControllerPandora::appendTracksToMpd Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763640] [Pandora] appendTracksToMpd: Added 1 track(s) to mpd Aug 17 11:19:23 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand addid Aug 17 11:19:23 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand play Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:19:23 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:19:23 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:19:23 volumio volumio[1020]: error: Upnp client error: Error: This socket has been ended by the other party Aug 17 11:19:23 volumio volumio[1020]: error: updateQueue error: null Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 49ms Aug 17 11:19:23 volumio volumio[1020]: info: sendMpdCommand addid took 43 milliseconds Aug 17 11:19:23 volumio volumio[1020]: info: sendMpdCommand play took 42 milliseconds Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 41ms Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 39ms Aug 17 11:19:23 volumio volumio[1020]: verbose: MPD COMMAND [object Object] Aug 17 11:19:23 volumio volumio[1020]: verbose: MPD COMMAND [object Object] Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763689] ControllerPandora::pushState Aug 17 11:19:23 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:23 volumio volumio[1020]: verbose: STATE SERVICE {"service":"pandora","type":"song","trackType":"mp3","title":"All the Things She Said (Metal Version)","name":"All the Things She Said (Metal Version)","artist":"Leo (Leo Moracchioli)","album":"Leo Metal, Vol. 25","albumart":"http://mediaserver-cont-sv5-2-v4v6.pandora.com/images/48/23/70/8a/84464db4a8de803cf54d2813/1080W_1080H.jpg","realUri":"http://audio-usc-mp1-t3-1-v4v6.pandora.com/access/2903035133559225830.mp3?version=5&lid=3067716&token=4agjXvTJQA16wWzkIMBb8QBXoByWcJF8qaToL%2FYPc8whRAPi0%2BlsqAfKKFDSkGaTjBLbbBLm1hPLwsKhXq%2BklZYCb6%2BPMoposk06RHGs9UZif55uyL1UkbdUcI6hC%2Bi0XE1XykV13hH8lHERZhpmtcQNRko%2FnzymVIUyroEXD9%2FJZS8EGGhoXBuQEzjujT%2FP90YrkI2FApwQbtSh2828hi4aFEFDv8XIcsBCBL3KCVYZBLkEdb8NsTw3U%2BDeFpgthZxgObU0L6F1tKAcL5MhZRYEGYSvgcdW1P4DvKf50NPYv3XXykDX%2FI8H0zXJau0apiHNsVxAxw8Anf1byGPITg%3D%3D","isStreaming":true,"duration":257,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"uri":"http://audio-usc-mp1-t3-1-v4v6.pandora.com/access/2903035133559225830.mp3?version=5&lid=3067716&token=4agjXvTJQA16wWzkIMBb8QBXoByWcJF8qaToL%2FYPc8whRAPi0%2BlsqAfKKFDSkGaTjBLbbBLm1hPLwsKhXq%2BklZYCb6%2BPMoposk06RHGs9UZif55uyL1UkbdUcI6hC%2Bi0XE1XykV13hH8lHERZhpmtcQNRko%2FnzymVIUyroEXD9%2FJZS8EGGhoXBuQEzjujT%2FP90YrkI2FApwQbtSh2828hi4aFEFDv8XIcsBCBL3KCVYZBLkEdb8NsTw3U%2BDeFpgthZxgObU0L6F1tKAcL5MhZRYEGYSvgcdW1P4DvKf50NPYv3XXykDX%2FI8H0zXJau0apiHNsVxAxw8Anf1byGPITg%3D%3D","seek":0,"status":"play"} Aug 17 11:19:23 volumio volumio[1020]: verbose: CURRENT POSITION 200 Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::syncState stateService play Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::syncState currentStatus stop Aug 17 11:19:23 volumio volumio[1020]: info: CoreStateMachine::setConsumeUpdateService pandora Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763691] ControllerPandora::fetchAndAddTracks Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763691] ControllerPandora::getStationTracks Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763692] [Pandora] PandoraHandler::getSongMaxDiff: -12 Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763692] ControllerPandora::fetchAndAddTracks::getSqInfo Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763693] ControllerPandora::getStationTracks Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763694] [Pandora] fetchAndAddTracks: diff1: -12 sQPos1: 0 Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763694] [Pandora] fetchAndAddTracks: Fetching tracks Aug 17 11:19:23 volumio volumio[1020]: info: [1723918763694] ControllerPandora::PandoraHandler::fillStationData Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 27ms Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 9ms Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 7ms Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: Aug 17 11:19:23 volumio volumio[1020]: ---------------------------- MPD announces system playlist update Aug 17 11:19:23 volumio volumio[1020]: info: Ignoring MPD Status Update Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 9ms Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 7ms Aug 17 11:19:23 volumio volumio[1020]: info: ------------------------------ 5ms Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764042] ControllerPandora::PandoraHandler::fetchTracks::fetchStationPlaylist Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764299] [Pandora] PandoraHandler::fetchTracks::fetchStationPlaylist: Retrieved Leo (Leo Moracchioli) Radio playlist Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764300] ControllerPandora::PandoraHandler::fetchTracks::fillNewTracks Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764301] [Pandora] PandoraHandler::fetchTracks::fillNewTracks: Fetched 4 track(s) Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::addQueueItems Aug 17 11:19:24 volumio volumio[1020]: info: Preload queue cleared Aug 17 11:19:24 volumio volumio[1020]: info: Adding Item to queue: /pandora/stationToken=4565853786759679812trackId=8809261229747036486 Aug 17 11:19:24 volumio volumio[1020]: info: Exploding uri /pandora/stationToken=4565853786759679812trackId=8809261229747036486 in service pandora Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764302] ControllerPandora::explodeUri Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: Adding Item to queue: /pandora/stationToken=4565853786759679812trackId=4858170584258656692 Aug 17 11:19:24 volumio volumio[1020]: info: Exploding uri /pandora/stationToken=4565853786759679812trackId=4858170584258656692 in service pandora Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764303] ControllerPandora::explodeUri Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: Adding Item to queue: /pandora/stationToken=4565853786759679812trackId=7669885551246376772 Aug 17 11:19:24 volumio volumio[1020]: info: Exploding uri /pandora/stationToken=4565853786759679812trackId=7669885551246376772 in service pandora Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764304] ControllerPandora::explodeUri Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: Adding Item to queue: /pandora/stationToken=4565853786759679812trackId=6314781193194479077 Aug 17 11:19:24 volumio volumio[1020]: info: Exploding uri /pandora/stationToken=4565853786759679812trackId=6314781193194479077 in service pandora Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764305] ControllerPandora::explodeUri Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::volumioPushQueue Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::saveQueue Aug 17 11:19:24 volumio volumio[1020]: info: CoreStateMachine::updateTrackBlock Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrackBlock Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764358] ControllerPandora::getStationTracks Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764359] [Pandora] PandoraHandler::getSongMaxDiff: -8 Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764666] ControllerPandora::pandoraListener Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::getState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand status Aug 17 11:19:24 volumio volumio[1020]: info: Aug 17 11:19:24 volumio volumio[1020]: ---------------------------- MPD announces state update: player Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::getState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand status Aug 17 11:19:24 volumio volumio[1020]: info: Aug 17 11:19:24 volumio volumio[1020]: ---------------------------- MPD announces state update: player Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::getState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand status Aug 17 11:19:24 volumio volumio[1020]: info: Aug 17 11:19:24 volumio volumio[1020]: ---------------------------- MPD announces state update: player Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::getState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand status Aug 17 11:19:24 volumio volumio[1020]: info: Aug 17 11:19:24 volumio volumio[1020]: ---------------------------- MPD announces state update: player Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand status took 8 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand status took 8 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::getState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand status Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand status took 12 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand status took 11 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand status took 7 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand playlistinfo took 7 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand playlistinfo took 6 milliseconds Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseTrackInfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseTrackInfo Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:24 volumio volumio[1020]: info: [1723918764692] ControllerPandora::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:24 volumio volumio[1020]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":257,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"All the Things She Said (Metal Version)","artist":"Leo (Leo Moracchioli)","album":"Leo Metal, Vol. 25","uri":"http://audio-usc-mp1-t3-1-v4v6.pandora.com/access/2903035133559225830.mp3?version=5&lid=3067716&token=4agjXvTJQA16wWzkIMBb8QBXoByWcJF8qaToL%2FYPc8whRAPi0%2BlsqAfKKFDSkGaTjBLbbBLm1hPLwsKhXq%2BklZYCb6%2BPMoposk06RHGs9UZif55uyL1UkbdUcI6hC%2Bi0XE1XykV13hH8lHERZhpmtcQNRko%2FnzymVIUyroEXD9%2FJZS8EGGhoXBuQEzjujT%2FP90YrkI2FApwQbtSh2828hi4aFEFDv8XIcsBCBL3KCVYZBLkEdb8NsTw3U%2BDeFpgthZxgObU0L6F1tKAcL5MhZRYEGYSvgcdW1P4DvKf50NPYv3XXykDX%2FI8H0zXJau0apiHNsVxAxw8Anf1byGPITg%3D%3D","trackType":"mp3"} Aug 17 11:19:24 volumio volumio[1020]: verbose: CURRENT POSITION 200 Aug 17 11:19:24 volumio volumio[1020]: info: CoreStateMachine::syncState stateService play Aug 17 11:19:24 volumio volumio[1020]: info: CoreStateMachine::syncState currentStatus play Aug 17 11:19:24 volumio volumio[1020]: info: Received an update from plugin. extracting info from payload Aug 17 11:19:24 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreStateMachine::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::volumioPushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreStateMachine::setConsumeUpdateService pandora Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:24 volumio volumio[1020]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current pandora Received mpd Aug 17 11:19:24 volumio volumio[1020]: info: ------------------------------ 81ms Aug 17 11:19:24 volumio volumio[1020]: info: Aug 17 11:19:24 volumio volumio[1020]: ---------------------------- MPD announces state update: player Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::getState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand status Aug 17 11:19:24 volumio volumio[1020]: info: Aug 17 11:19:24 volumio volumio[1020]: ---------------------------- MPD announces state update: player Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::getState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand status Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand playlistinfo took 70 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand playlistinfo took 70 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand playlistinfo took 70 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand status took 8 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand status took 6 milliseconds Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseTrackInfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseTrackInfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseTrackInfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseState Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:24 volumio volumio[1020]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current pandora Received mpd Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:24 volumio volumio[1020]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current pandora Received mpd Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:24 volumio volumio[1020]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current pandora Received mpd Aug 17 11:19:24 volumio volumio[1020]: info: ------------------------------ 102ms Aug 17 11:19:24 volumio volumio[1020]: info: ------------------------------ 101ms Aug 17 11:19:24 volumio volumio[1020]: info: ------------------------------ 98ms Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::volumioGetQueue Aug 17 11:19:24 volumio volumio[1020]: info: CoreStateMachine::getQueue Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getQueue Aug 17 11:19:24 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:19:24 volumio volumio[1020]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand playlistinfo took 25 milliseconds Aug 17 11:19:24 volumio volumio[1020]: info: sendMpdCommand playlistinfo took 25 milliseconds Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseTrackInfo Aug 17 11:19:24 volumio volumio[1020]: verbose: ControllerMpd::parseTrackInfo Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:24 volumio volumio[1020]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current pandora Received mpd Aug 17 11:19:24 volumio volumio[1020]: info: ControllerMpd::pushState Aug 17 11:19:24 volumio volumio[1020]: info: CoreCommandRouter::servicePushState Aug 17 11:19:24 volumio volumio[1020]: info: CorePlayQueue::getTrack 200 Aug 17 11:19:24 volumio volumio[1020]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current pandora Received mpd Aug 17 11:19:24 volumio volumio[1020]: info: ------------------------------ 45ms Aug 17 11:19:24 volumio volumio[1020]: info: ------------------------------ 43ms Aug 17 11:19:36 volumio go-librespot[6792]: time="2024-08-17T11:19:36-07:00" level=debug msg="fetched chunk 7/10, size: 524288" uri="spotify:track:3Xxvk3YPB4EfL2pdhrIwha" Aug 17 11:19:42 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 17 11:19:42 volumio volumio[1020]: info: Preload queue cleared Aug 17 11:19:44 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 17 11:19:45 volumio volumio[1020]: info: Preload queue cleared Aug 17 11:19:46 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 17 11:19:46 volumio volumio[1020]: info: Preload queue cleared Aug 17 11:19:48 volumio volumio[1020]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 17 11:19:48 volumio volumio[1020]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 17 11:19:48 volumio volumio[1020]: TypeError: Cannot read property 'length' of undefined Aug 17 11:19:48 volumio volumio[1020]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Aug 17 11:19:48 volumio volumio[1020]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Aug 17 11:19:48 volumio volumio[1020]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Aug 17 11:19:48 volumio volumio[1020]: at Parser.emit (events.js:315:20) Aug 17 11:19:48 volumio volumio[1020]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Aug 17 11:19:48 volumio volumio[1020]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Aug 17 11:19:48 volumio volumio[1020]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Aug 17 11:19:48 volumio volumio[1020]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Aug 17 11:19:48 volumio volumio[1020]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Aug 17 11:19:48 volumio volumio[1020]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Aug 17 11:19:48 volumio volumio[1020]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Aug 17 11:19:48 volumio volumio[1020]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Aug 17 11:19:48 volumio volumio[1020]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Aug 17 11:19:48 volumio volumio[1020]: at IncomingMessage.emit (events.js:327:22) Aug 17 11:19:48 volumio volumio[1020]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 17 11:19:48 volumio volumio[1020]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 17 11:19:48 volumio volumio[1020]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 17 11:19:49 volumio sudo[11689]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-17 11:18 Aug 17 11:19:49 volumio sudo[11689]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"