-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Sat 2025-03-15 17:51:55 CET. -- Mar 15 17:50:07 volumio go-librespot[9623]: time="2025-03-15T17:50:07+01:00" level=debug msg="fetched chunk 18/23, size: 524288" uri="spotify:track:0z3Voyxi0FH0SQBc7c4wri" Mar 15 17:50:10 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: 80s80s , handleBrowseUri Mar 15 17:50:10 volumio volumio[902]: info: [1742057410444] [80s80s] handleBrowseUri curUri: 80s80s Mar 15 17:50:10 volumio volumio[902]: info: Preload queue cleared Mar 15 17:50:12 volumio go-librespot[9623]: time="2025-03-15T17:50:12+01:00" level=trace msg="sent dealer ping" Mar 15 17:50:12 volumio go-librespot[9623]: time="2025-03-15T17:50:12+01:00" level=trace msg="received dealer pong" Mar 15 17:50:15 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Mar 15 17:50:15 volumio volumio[902]: info: Preload queue cleared Mar 15 17:50:17 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Mar 15 17:50:17 volumio volumio[902]: info: Preload queue cleared Mar 15 17:50:18 volumio volumio[902]: info: Preload queue cleared Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::ClearQueue Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::stop Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::serviceStop Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::serviceStop Mar 15 17:50:18 volumio volumio[902]: info: Spotify Stop Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: SPOTIFY STOP Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: {"status":"play","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","codec":"ogg","seek":158497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":86,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Mar 15 17:50:18 volumio volumio[902]: info: Sending Spotify command to local API: /player/pause Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::clearPlayQueue Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::saveQueue Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioPushQueue Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::addQueueItems Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::addQueueItems Mar 15 17:50:18 volumio volumio[902]: info: Preload queue cleared Mar 15 17:50:18 volumio volumio[902]: info: Adding Item to queue: http://opml.radiotime.com/Tune.ashx?id=s73452 Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioPushQueue Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::saveQueue Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::updateTrackBlock Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::getTrackBlock Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioPlay Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::play index 0 Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::stop Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::stPlaybackTimer Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::updateTrackBlock Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::getTrackBlock Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::getTrack 0 Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::serviceStop Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::getTrack 0 Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::serviceStop Mar 15 17:50:18 volumio volumio[902]: info: [1742057418325] ControllerWebradio::stop Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand stop Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:18 volumio go-librespot[9623]: time="2025-03-15T17:50:18+01:00" level=debug msg="pause track at 193129ms" Mar 15 17:50:18 volumio volumio[902]: info: Mar 15 17:50:18 volumio volumio[902]: ---------------------------- MPD announces state update: player Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand stop took 35 milliseconds Mar 15 17:50:18 volumio volumio[902]: info: ControllerMpd::getState Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand status Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::play index undefined Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::getTrack 0 Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::startPlaybackTimer Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::getTrack 0 Mar 15 17:50:18 volumio volumio[902]: info: [1742057418362] ControllerWebradio::clearAddPlayTrack Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand stop Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand status took 3 milliseconds Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand stop took 1 milliseconds Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::parseState Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand clear Mar 15 17:50:18 volumio volumio[902]: info: Mar 15 17:50:18 volumio volumio[902]: ---------------------------- MPD announces system playlist update Mar 15 17:50:18 volumio volumio[902]: info: Ignoring MPD Status Update Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand clear took 2 milliseconds Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::parseTrackInfo Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand load "https://ice02.fluidstream.net/marilu.mp3?FLID=3" Mar 15 17:50:18 volumio volumio[902]: info: ControllerMpd::pushState Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::getTrack 0 Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:18 volumio volumio[902]: info: CorePlayQueue::getTrack 0 Mar 15 17:50:18 volumio volumio[902]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Mar 15 17:50:18 volumio volumio[902]: info: ------------------------------ 20ms Mar 15 17:50:18 volumio volumio[902]: error: updateQueue error: null Mar 15 17:50:18 volumio volumio[902]: info: ------------------------------ 15ms Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:18 volumio volumio[902]: info: touch_display: Setting screensaver timeout to 120 seconds. Mar 15 17:50:18 volumio go-librespot[9623]: time="2025-03-15T17:50:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:50:18 volumio go-librespot[9623]: time="2025-03-15T17:50:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:50:18 volumio go-librespot[9623]: time="2025-03-15T17:50:18+01:00" level=trace msg="emitting websocket event: paused" Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","play_origin":""}} Mar 15 17:50:18 volumio volumio[902]: info: Spotify is playing in volatile mode Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: UNSET VOLATILE Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: {"status":"stop","position":0,"title":"Radio Marilu","albumart":"http://cdn-radiotime-logos.tunein.com/s73452q.png","uri":"https://ice02.fluidstream.net/marilu.mp3?FLID=3","trackType":"webradio","seek":0,"samplerate":"","bitdepth":"","channels":0,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":86,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"webradio","updatedb":false,"volatile":false,"service":"webradio"} Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: {"status":"pause","service":"spop","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","seek":192497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","play_origin":""}} Mar 15 17:50:18 volumio volumio[902]: info: Spotify is playing in volatile mode Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: UNSET VOLATILE Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: {"status":"stop","position":0,"title":"Radio Marilu","albumart":"http://cdn-radiotime-logos.tunein.com/s73452q.png","uri":"https://ice02.fluidstream.net/marilu.mp3?FLID=3","trackType":"webradio","seek":0,"samplerate":"","bitdepth":"","channels":0,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":86,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"webradio","updatedb":false,"volatile":false,"service":"webradio"} Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: {"status":"pause","service":"spop","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","seek":158497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:18 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand add "https://ice02.fluidstream.net/marilu.mp3?FLID=3" Mar 15 17:50:18 volumio volumio[902]: info: Mar 15 17:50:18 volumio volumio[902]: ---------------------------- MPD announces system playlist update Mar 15 17:50:18 volumio volumio[902]: info: Ignoring MPD Status Update Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand add "https://ice02.fluidstream.net/marilu.mp3?FLID=3" took 2 milliseconds Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand play Mar 15 17:50:18 volumio volumio[902]: info: ------------------------------ 2ms Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand play took 3 milliseconds Mar 15 17:50:18 volumio volumio[902]: info: Mar 15 17:50:18 volumio volumio[902]: ---------------------------- MPD announces state update: player Mar 15 17:50:18 volumio volumio[902]: info: ControllerMpd::getState Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand status Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand status took 2 milliseconds Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::parseState Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 15 17:50:18 volumio volumio[902]: info: sendMpdCommand playlistinfo took 1 milliseconds Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::parseTrackInfo Mar 15 17:50:18 volumio volumio[902]: info: ControllerMpd::pushState Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:18 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:18 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:18 volumio volumio[902]: info: ------------------------------ 14ms Mar 15 17:50:18 volumio volumio[902]: info: Mar 15 17:50:18 volumio volumio[902]: ---------------------------- MPD announces system playlist update Mar 15 17:50:18 volumio volumio[902]: info: Ignoring MPD Status Update Mar 15 17:50:18 volumio volumio[902]: info: Mar 15 17:50:18 volumio volumio[902]: ---------------------------- MPD announces state update: player Mar 15 17:50:18 volumio volumio[902]: info: ControllerMpd::getState Mar 15 17:50:18 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand status Mar 15 17:50:19 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:19 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:19 volumio volumio[902]: info: Mar 15 17:50:19 volumio volumio[902]: ---------------------------- MPD announces system playlist update Mar 15 17:50:19 volumio volumio[902]: info: Ignoring MPD Status Update Mar 15 17:50:19 volumio volumio[902]: info: Mar 15 17:50:19 volumio volumio[902]: ---------------------------- MPD announces state update: player Mar 15 17:50:19 volumio volumio[902]: info: ControllerMpd::getState Mar 15 17:50:19 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand status Mar 15 17:50:19 volumio volumio[902]: info: ------------------------------ 9ms Mar 15 17:50:19 volumio volumio[902]: info: sendMpdCommand status took 7 milliseconds Mar 15 17:50:19 volumio volumio[902]: verbose: ControllerMpd::parseState Mar 15 17:50:19 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 15 17:50:19 volumio volumio[902]: info: ------------------------------ 4ms Mar 15 17:50:19 volumio volumio[902]: info: sendMpdCommand status took 3 milliseconds Mar 15 17:50:19 volumio volumio[902]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 15 17:50:19 volumio volumio[902]: verbose: ControllerMpd::parseState Mar 15 17:50:19 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 15 17:50:19 volumio volumio[902]: verbose: ControllerMpd::parseTrackInfo Mar 15 17:50:19 volumio volumio[902]: info: ControllerMpd::pushState Mar 15 17:50:19 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:19 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:19 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:19 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:19 volumio volumio[902]: info: ------------------------------ 21ms Mar 15 17:50:19 volumio volumio[902]: info: sendMpdCommand playlistinfo took 12 milliseconds Mar 15 17:50:19 volumio volumio[902]: verbose: ControllerMpd::parseTrackInfo Mar 15 17:50:19 volumio volumio[902]: info: ControllerMpd::pushState Mar 15 17:50:19 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:19 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:19 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:19 volumio volumio[902]: info: ------------------------------ 32ms Mar 15 17:50:19 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:19 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:19 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:19 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:20 volumio ntpd[803]: 212.45.144.206 local addr 192.168.3.127 -> Mar 15 17:50:20 volumio volumio[902]: info: CoreCommandRouter::volumioPause Mar 15 17:50:20 volumio volumio[902]: info: CoreStateMachine::pause Mar 15 17:50:20 volumio volumio[902]: info: CoreStateMachine::stPlaybackTimer Mar 15 17:50:20 volumio volumio[902]: info: CoreStateMachine::servicePause Mar 15 17:50:20 volumio volumio[902]: info: CoreCommandRouter::servicePause Mar 15 17:50:20 volumio volumio[902]: info: ControllerMpd::pause Mar 15 17:50:20 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand pause Mar 15 17:50:20 volumio volumio[902]: info: Mar 15 17:50:20 volumio volumio[902]: ---------------------------- MPD announces state update: player Mar 15 17:50:20 volumio volumio[902]: info: sendMpdCommand pause took 2 milliseconds Mar 15 17:50:20 volumio volumio[902]: info: ControllerMpd::getState Mar 15 17:50:20 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand status Mar 15 17:50:20 volumio volumio[902]: info: sendMpdCommand status took 1 milliseconds Mar 15 17:50:20 volumio volumio[902]: verbose: ControllerMpd::parseState Mar 15 17:50:20 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 15 17:50:20 volumio volumio[902]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 15 17:50:20 volumio volumio[902]: verbose: ControllerMpd::parseTrackInfo Mar 15 17:50:20 volumio volumio[902]: info: ControllerMpd::pushState Mar 15 17:50:20 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:20 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:20 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:20 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:20 volumio volumio[902]: info: ------------------------------ 17ms Mar 15 17:50:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:20 volumio volumio[902]: info: touch_display: Setting screensaver timeout to 120 seconds. Mar 15 17:50:31 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 15 17:50:31 volumio volumio[902]: info: In handleBrowseUri, curUri=spotify Mar 15 17:50:31 volumio volumio[902]: info: Preload queue cleared Mar 15 17:50:31 volumio volumio[902]: info: Preload queue cleared Mar 15 17:50:31 volumio volumio[902]: info: Preload queue cleared Mar 15 17:50:36 volumio volumio[902]: info: CoreCommandRouter::volumioVolatilePlay Mar 15 17:50:36 volumio volumio[902]: info: CoreStateMachine::volatilePlay Mar 15 17:50:36 volumio volumio[902]: info: ControllerMpd::play undefined Mar 15 17:50:36 volumio volumio[902]: verbose: ControllerMpd::sendMpdCommand play Mar 15 17:50:36 volumio volumio[902]: error: MPD error: Cannot read property 'toString' of undefined Mar 15 17:50:36 volumio volumio[902]: error: Cannot read property 'toString' of undefined Mar 15 17:50:36 volumio go-librespot[9623]: time="2025-03-15T17:50:36+01:00" level=trace msg="received accesspoint ping" Mar 15 17:50:36 volumio go-librespot[9623]: time="2025-03-15T17:50:36+01:00" level=trace msg="received accesspoint pong ack" Mar 15 17:50:42 volumio go-librespot[9623]: time="2025-03-15T17:50:42+01:00" level=trace msg="sent dealer ping" Mar 15 17:50:42 volumio go-librespot[9623]: time="2025-03-15T17:50:42+01:00" level=trace msg="received dealer pong" Mar 15 17:50:51 volumio go-librespot[9623]: time="2025-03-15T17:50:51+01:00" level=debug msg="handling resume player command from 90aba5faacde374bf11326ea7892bf664fe1a953" Mar 15 17:50:51 volumio go-librespot[9623]: time="2025-03-15T17:50:51+01:00" level=trace msg="seek to 193129ms (diff: 112ms, samples: 8516988, bytes: 8322346)" uri="spotify:track:0z3Voyxi0FH0SQBc7c4wri" Mar 15 17:50:51 volumio go-librespot[9623]: time="2025-03-15T17:50:51+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Mar 15 17:50:51 volumio go-librespot[9623]: time="2025-03-15T17:50:51+01:00" level=debug msg="resume track at 193017ms" Mar 15 17:50:51 volumio go-librespot[9623]: time="2025-03-15T17:50:51+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:50:51 volumio go-librespot[9623]: time="2025-03-15T17:50:51+01:00" level=trace msg="scheduling prefetch in 66s" Mar 15 17:50:51 volumio go-librespot[9623]: time="2025-03-15T17:50:51+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 17:50:52 volumio go-librespot[9623]: time="2025-03-15T17:50:52+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:50:52 volumio go-librespot[9623]: time="2025-03-15T17:50:52+01:00" level=trace msg="emitting websocket event: playing" Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","play_origin":""}} Mar 15 17:50:52 volumio volumio[902]: info: Spotify is playing in volatile mode Mar 15 17:50:52 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: UNSET VOLATILE Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: {"status":"pause","title":"REM - IT'S THE END OF THE WORLD AS W","artist":"Marilu","album":null,"albumart":"/albumart","uri":"https://ice02.fluidstream.net/marilu.mp3?FLID=3","trackType":"mp3","codec":"","seek":2855,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"repeat":false,"consume":false,"volume":86,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true} Mar 15 17:50:52 volumio volumio[902]: info: Setting Spotify stop after unset volatile call Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","seek":192497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:52 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","play_origin":""}} Mar 15 17:50:52 volumio volumio[902]: info: Spotify is playing in volatile mode Mar 15 17:50:52 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: UNSET VOLATILE Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: {"status":"pause","title":"REM - IT'S THE END OF THE WORLD AS W","artist":"Marilu","album":null,"albumart":"/albumart","uri":"https://ice02.fluidstream.net/marilu.mp3?FLID=3","trackType":"mp3","codec":"","seek":2855,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"repeat":false,"consume":false,"volume":86,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true} Mar 15 17:50:52 volumio volumio[902]: info: Setting Spotify stop after unset volatile call Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","seek":158497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:52 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","seek":192497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:52 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","seek":158497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:50:52 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:50:52 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:50:52 volumio volumio[902]: info: Spotify Stop Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: SPOTIFY STOP Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: {"status":"play","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","codec":"ogg","seek":158497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":86,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Mar 15 17:50:52 volumio volumio[902]: info: Spotify Stop Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: SPOTIFY STOP Mar 15 17:50:52 volumio volumio[902]: SPOTIFY: {"status":"play","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","codec":"ogg","seek":158497,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":86,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Mar 15 17:50:53 volumio go-librespot[9623]: time="2025-03-15T17:50:53+01:00" level=debug msg="fetched chunk 19/23, size: 524288" uri="spotify:track:0z3Voyxi0FH0SQBc7c4wri" Mar 15 17:50:59 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:50:59 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:50:59 volumio volumio[902]: info: Spotify next Mar 15 17:50:59 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:50:59 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:05 volumio go-librespot[9623]: time="2025-03-15T17:51:05+01:00" level=debug msg="fetched chunk 20/23, size: 524288" uri="spotify:track:0z3Voyxi0FH0SQBc7c4wri" Mar 15 17:51:05 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:05 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:05 volumio volumio[902]: info: Spotify next Mar 15 17:51:05 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:05 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:06 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:06 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:06 volumio volumio[902]: info: Spotify next Mar 15 17:51:06 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:06 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:06 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:06 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:06 volumio volumio[902]: info: Spotify next Mar 15 17:51:06 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:06 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:07 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:07 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:07 volumio volumio[902]: info: Spotify next Mar 15 17:51:07 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:07 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:07 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:07 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:07 volumio volumio[902]: info: Spotify next Mar 15 17:51:07 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:07 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:07 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:07 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:07 volumio volumio[902]: info: Spotify next Mar 15 17:51:07 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:07 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:08 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:08 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:08 volumio volumio[902]: info: Spotify next Mar 15 17:51:08 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:08 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:08 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:08 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:08 volumio volumio[902]: info: Spotify next Mar 15 17:51:08 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:08 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:11 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:11 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:11 volumio volumio[902]: info: Spotify next Mar 15 17:51:11 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:11 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:11 volumio volumio[902]: info: CoreCommandRouter::volumioPrevious Mar 15 17:51:11 volumio volumio[902]: info: Spotify previous Mar 15 17:51:11 volumio volumio[902]: info: Sending Spotify command to local API: /player/prev Mar 15 17:51:11 volumio go-librespot[9623]: time="2025-03-15T17:51:11+01:00" level=debug msg="seek track to 0ms" Mar 15 17:51:11 volumio go-librespot[9623]: time="2025-03-15T17:51:11+01:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0z3Voyxi0FH0SQBc7c4wri" Mar 15 17:51:12 volumio go-librespot[9623]: time="2025-03-15T17:51:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:51:12 volumio go-librespot[9623]: time="2025-03-15T17:51:12+01:00" level=trace msg="scheduling prefetch in 259s" Mar 15 17:51:12 volumio go-librespot[9623]: time="2025-03-15T17:51:12+01:00" level=trace msg="emitting websocket event: seek" Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","position":0,"duration":288986,"play_origin":""}} Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","seek":0,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:12 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:12 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:12 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:51:12 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","position":0,"duration":288986,"play_origin":""}} Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Cosas De La Vida","artist":"Eros Ramazzotti","album":"Todo Historias","albumart":"https://i.scdn.co/image/ab67616d00001e02c8729fbeebb389680f1e6ee5","uri":"spotify:track:0z3Voyxi0FH0SQBc7c4wri","trackType":"spotify","seek":0,"duration":288,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:12 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:12 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:12 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:12 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:12 volumio go-librespot[9623]: time="2025-03-15T17:51:12+01:00" level=trace msg="sent dealer ping" Mar 15 17:51:12 volumio go-librespot[9623]: time="2025-03-15T17:51:12+01:00" level=trace msg="received dealer pong" Mar 15 17:51:13 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:13 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:13 volumio volumio[902]: info: Spotify next Mar 15 17:51:13 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:13 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:18 volumio go-librespot[9623]: time="2025-03-15T17:51:18+01:00" level=debug msg="handling play player command from 90aba5faacde374bf11326ea7892bf664fe1a953" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EIXGeVv2HPIZQ" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EIXGeVv2HPIZQ" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:148uoUpRp6FJK5qYoXijwm" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 17:51:19 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","play_origin":"playlist"}} Mar 15 17:51:19 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","play_origin":"playlist"}} Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=debug msg="selected format OGG_VORBIS_320 (4cbf9d2c6778d2ba735b2e5c9f0b753790b0b92e)" uri="spotify:track:148uoUpRp6FJK5qYoXijwm" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=debug msg="requested aes key for file 4cbf9d2c6778d2ba735b2e5c9f0b753790b0b92e, gid: 148uoUpRp6FJK5qYoXijwm" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=debug msg="fetched first chunk of 23, total size is 11854140 bytes" uri="spotify:track:148uoUpRp6FJK5qYoXijwm" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 17:51:19 volumio go-librespot[9623]: time="2025-03-15T17:51:19+01:00" level=info msg="loaded track \"Notte prima degli esami\" (paused: false, position: 0ms, duration: 291506ms, prefetched: false)" uri="spotify:track:148uoUpRp6FJK5qYoXijwm" Mar 15 17:51:20 volumio go-librespot[9623]: time="2025-03-15T17:51:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:51:20 volumio go-librespot[9623]: time="2025-03-15T17:51:20+01:00" level=trace msg="scheduling prefetch in 261s" Mar 15 17:51:20 volumio go-librespot[9623]: time="2025-03-15T17:51:20+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 17:51:20 volumio go-librespot[9623]: time="2025-03-15T17:51:20+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","name":"Notte prima degli esami","artist_names":["Antonello Venditti"],"album_name":"Cuore","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e879669fba72d6e882318d87","position":0,"duration":291506,"release_date":"year:1984 month:12 day:1","track_number":1,"disc_number":1}} Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","name":"Notte prima degli esami","artist_names":["Antonello Venditti"],"album_name":"Cuore","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e879669fba72d6e882318d87","position":0,"duration":291506,"release_date":"year:1984 month:12 day:1","track_number":1,"disc_number":1}} Mar 15 17:51:20 volumio go-librespot[9623]: time="2025-03-15T17:51:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:51:20 volumio go-librespot[9623]: time="2025-03-15T17:51:20+01:00" level=trace msg="emitting websocket event: playing" Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","play_origin":"playlist"}} Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Notte prima degli esami","artist":"Antonello Venditti","album":"Cuore","albumart":"https://i.scdn.co/image/ab67616d00001e02e879669fba72d6e882318d87","uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","trackType":"spotify","seek":0,"duration":291,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:20 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","play_origin":"playlist"}} Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Notte prima degli esami","artist":"Antonello Venditti","album":"Cuore","albumart":"https://i.scdn.co/image/ab67616d00001e02e879669fba72d6e882318d87","uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","trackType":"spotify","seek":0,"duration":291,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:20 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Notte prima degli esami","artist":"Antonello Venditti","album":"Cuore","albumart":"https://i.scdn.co/image/ab67616d00001e02e879669fba72d6e882318d87","uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","trackType":"spotify","seek":0,"duration":291,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:20 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Notte prima degli esami","artist":"Antonello Venditti","album":"Cuore","albumart":"https://i.scdn.co/image/ab67616d00001e02e879669fba72d6e882318d87","uri":"spotify:track:148uoUpRp6FJK5qYoXijwm","trackType":"spotify","seek":0,"duration":291,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:20 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:20 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:20 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:20 volumio go-librespot[9623]: time="2025-03-15T17:51:20+01:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:148uoUpRp6FJK5qYoXijwm" Mar 15 17:51:21 volumio go-librespot[9623]: time="2025-03-15T17:51:21+01:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:148uoUpRp6FJK5qYoXijwm" Mar 15 17:51:21 volumio go-librespot[9623]: time="2025-03-15T17:51:21+01:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:148uoUpRp6FJK5qYoXijwm" Mar 15 17:51:23 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:23 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:23 volumio volumio[902]: info: Spotify next Mar 15 17:51:23 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:23 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:24 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:24 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:24 volumio volumio[902]: info: Spotify next Mar 15 17:51:24 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:24 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:25 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:25 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:25 volumio volumio[902]: info: Spotify next Mar 15 17:51:25 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:25 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:25 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:25 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:25 volumio volumio[902]: info: Spotify next Mar 15 17:51:25 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:25 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:25 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:25 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:25 volumio volumio[902]: info: Spotify next Mar 15 17:51:25 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:25 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="handling skip_next player command from 90aba5faacde374bf11326ea7892bf664fe1a953" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","play_origin":"playlist"}} Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","play_origin":"playlist"}} Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="selected format OGG_VORBIS_320 (be3440bd5a00f4f4910f6d5920404cffff8f8516)" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="requested aes key for file be3440bd5a00f4f4910f6d5920404cffff8f8516, gid: 0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="fetched first chunk of 20, total size is 10219860 bytes" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=info msg="loaded track \"Piccola stella senza cielo\" (paused: false, position: 0ms, duration: 238893ms, prefetched: false)" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=trace msg="scheduling prefetch in 209s" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","name":"Piccola stella senza cielo","artist_names":["Ligabue"],"album_name":"Ligabue [Remastered Version]","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02aa98bbdb641ab2764893c3df","position":0,"duration":238893,"release_date":"year:1990","track_number":3,"disc_number":1}} Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","name":"Piccola stella senza cielo","artist_names":["Ligabue"],"album_name":"Ligabue [Remastered Version]","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02aa98bbdb641ab2764893c3df","position":0,"duration":238893,"release_date":"year:1990","track_number":3,"disc_number":1}} Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 17:51:28 volumio go-librespot[9623]: time="2025-03-15T17:51:28+01:00" level=trace msg="emitting websocket event: playing" Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","play_origin":"playlist"}} Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Piccola stella senza cielo","artist":"Ligabue","album":"Ligabue [Remastered Version]","albumart":"https://i.scdn.co/image/ab67616d00001e02aa98bbdb641ab2764893c3df","uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","trackType":"spotify","seek":0,"duration":238,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:28 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:28 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:28 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:51:28 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","play_origin":"playlist"}} Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Piccola stella senza cielo","artist":"Ligabue","album":"Ligabue [Remastered Version]","albumart":"https://i.scdn.co/image/ab67616d00001e02aa98bbdb641ab2764893c3df","uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","trackType":"spotify","seek":0,"duration":238,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:28 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:28 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:28 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:28 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:29 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:29 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Piccola stella senza cielo","artist":"Ligabue","album":"Ligabue [Remastered Version]","albumart":"https://i.scdn.co/image/ab67616d00001e02aa98bbdb641ab2764893c3df","uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","trackType":"spotify","seek":1000,"duration":238,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:29 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:29 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:29 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:51:29 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:29 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:29 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:29 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 17:51:29 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"Piccola stella senza cielo","artist":"Ligabue","album":"Ligabue [Remastered Version]","albumart":"https://i.scdn.co/image/ab67616d00001e02aa98bbdb641ab2764893c3df","uri":"spotify:track:0HpKuz1HfXxRzNnUqfwzgF","trackType":"spotify","seek":0,"duration":238,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 17:51:29 volumio volumio[902]: info: CoreCommandRouter::servicePushState Mar 15 17:51:29 volumio volumio[902]: info: CoreStateMachine::pushState Mar 15 17:51:29 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 17:51:29 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Mar 15 17:51:29 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:29 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 15 17:51:35 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:35 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:35 volumio volumio[902]: info: Spotify next Mar 15 17:51:35 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:35 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:36 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:36 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:36 volumio volumio[902]: info: Spotify next Mar 15 17:51:36 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:36 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:37 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:37 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:37 volumio volumio[902]: info: Spotify next Mar 15 17:51:37 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:37 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:38 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:38 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:38 volumio volumio[902]: info: Spotify next Mar 15 17:51:38 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:38 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:38 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:38 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:38 volumio volumio[902]: info: Spotify next Mar 15 17:51:38 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:38 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:38 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:38 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:38 volumio volumio[902]: info: Spotify next Mar 15 17:51:38 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:38 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:40 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:40 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:40 volumio volumio[902]: info: Spotify next Mar 15 17:51:40 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:40 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:40 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:40 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:40 volumio volumio[902]: info: Spotify next Mar 15 17:51:40 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:40 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:40 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:40 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:40 volumio volumio[902]: info: Spotify next Mar 15 17:51:40 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:40 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:40 volumio go-librespot[9623]: time="2025-03-15T17:51:40+01:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:40 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:40 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:40 volumio volumio[902]: info: Spotify next Mar 15 17:51:40 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:40 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:41 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:41 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:41 volumio volumio[902]: info: Spotify next Mar 15 17:51:41 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:41 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:41 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:41 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:41 volumio volumio[902]: info: Spotify next Mar 15 17:51:41 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:41 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:42 volumio go-librespot[9623]: time="2025-03-15T17:51:42+01:00" level=trace msg="sent dealer ping" Mar 15 17:51:42 volumio go-librespot[9623]: time="2025-03-15T17:51:42+01:00" level=trace msg="received dealer pong" Mar 15 17:51:43 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:43 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:43 volumio volumio[902]: info: Spotify next Mar 15 17:51:43 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:43 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:43 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:43 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:43 volumio volumio[902]: info: Spotify next Mar 15 17:51:43 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:43 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:44 volumio volumio[902]: info: CoreCommandRouter::volumioNext Mar 15 17:51:44 volumio volumio[902]: info: CoreStateMachine::next Mar 15 17:51:44 volumio volumio[902]: info: Spotify next Mar 15 17:51:44 volumio volumio[902]: info: Sending Spotify command to local API: /player/next Mar 15 17:51:44 volumio volumio[902]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request Mar 15 17:51:52 volumio go-librespot[9623]: time="2025-03-15T17:51:52+01:00" level=debug msg="fetched chunk 5/19, size: 524288" uri="spotify:track:0HpKuz1HfXxRzNnUqfwzgF" Mar 15 17:51:54 volumio volumio[902]: info: [1742057514875] [80s80s] Pushing the next song state DJ Bobo - Let the Dream Come True and getting next track. Mar 15 17:51:54 volumio volumio[902]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 15 17:51:54 volumio volumio[902]: TypeError: Cannot set property 'name' of undefined Mar 15 17:51:54 volumio volumio[902]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Mar 15 17:51:54 volumio volumio[902]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Mar 15 17:51:54 volumio volumio[902]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Mar 15 17:51:54 volumio volumio[902]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Mar 15 17:51:54 volumio volumio[902]: at processImmediate (internal/timers.js:461:21) Mar 15 17:51:54 volumio volumio[902]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 15 17:51:55 volumio sudo[10178]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-15 17:50 Mar 15 17:51:55 volumio sudo[10178]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="a01a833dd28483f88cb390596f5090b7187992af" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 27 Feb 2025 11:42:54 AM CET" VOLUMIO_VERSION="3.795" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4049a67f1c09d4a94e033ba35a80a144"