May 29 08:29:04 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:29:04 volumio volumio[1239]: info: In handleBrowseUri, curUri=spotify May 29 08:29:04 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:04 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:04 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:04 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:06 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:29:06 volumio volumio[1239]: info: In handleBrowseUri, curUri=spotify/mytracks May 29 08:29:07 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:08 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::ClearQueue May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::stPlaybackTimer May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::updateTrackBlock May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrackBlock May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::pushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::serviceStop May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::serviceStop May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService mpd May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::stop May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand stop May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::clearPlayQueue May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::addQueueItems May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::addQueueItems May 29 08:29:08 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:08 volumio volumio[1239]: info: Adding Item to queue: spotify:track:1izTPgfFEyvc0hl7uYAzGt May 29 08:29:08 volumio volumio[1239]: info: Using cached record of: spotify:track:1izTPgfFEyvc0hl7uYAzGt May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::updateTrackBlock May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrackBlock May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::play index 0 May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: [1748496548806] ControllerSpotify::clearAddPlayTrack May 29 08:29:08 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:08 volumio volumio[1239]: info: PeppyMeterBasic ---peppymeterbasic status stop May 29 08:29:08 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:29:08 volumio volumio[1239]: info: May 29 08:29:08 volumio volumio[1239]: ---------------------------- MPD announces state update: player May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand stop took 21 milliseconds May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::getState May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand status May 29 08:29:08 volumio volumio[1239]: info: May 29 08:29:08 volumio volumio[1239]: ---------------------------- MPD announces state update: player May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::getState May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand status May 29 08:29:08 volumio volumio[1239]: info: May 29 08:29:08 volumio volumio[1239]: ---------------------------- MPD announces state update: player May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::getState May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand status May 29 08:29:08 volumio volumio[1239]: info: May 29 08:29:08 volumio volumio[1239]: ---------------------------- MPD announces state update: player May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::getState May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand status May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand status took 1 milliseconds May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand status took 2 milliseconds May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand status took 1 milliseconds May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand status took 1 milliseconds May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::parseState May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::parseState May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::parseState May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::parseState May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand playlistinfo took 1 milliseconds May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand playlistinfo took 1 milliseconds May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand playlistinfo took 1 milliseconds May 29 08:29:08 volumio volumio[1239]: info: sendMpdCommand playlistinfo took 1 milliseconds May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::parseTrackInfo May 29 08:29:08 volumio sudo[2472]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service May 29 08:29:08 volumio sudo[2472]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::parseTrackInfo May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::parseTrackInfo May 29 08:29:08 volumio volumio[1239]: verbose: ControllerMpd::parseTrackInfo May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::pushState May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::servicePushState May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::pushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::pushState May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::servicePushState May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::pushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::pushState May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::servicePushState May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::pushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 29 08:29:08 volumio volumio[1239]: info: ControllerMpd::pushState May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::servicePushState May 29 08:29:08 volumio volumio[1239]: info: CoreStateMachine::pushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState May 29 08:29:08 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:08 volumio volumio[1239]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 29 08:29:08 volumio systemd[1]: Stopping peppymeterbasic.service - peppymeterbasic Daemon... May 29 08:29:08 volumio volumio[1239]: info: ------------------------------ 21ms May 29 08:29:08 volumio volumio[1239]: info: ------------------------------ 20ms May 29 08:29:08 volumio volumio[1239]: info: ------------------------------ 21ms May 29 08:29:08 volumio volumio[1239]: info: ------------------------------ 20ms May 29 08:29:08 volumio volumio[1239]: info: PeppyMeterBasic ---peppymeterbasic status stop May 29 08:29:08 volumio volumio[1239]: info: PeppyMeterBasic ---peppymeterbasic status stop May 29 08:29:08 volumio volumio[1239]: info: PeppyMeterBasic ---peppymeterbasic status stop May 29 08:29:08 volumio sudo[2477]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service May 29 08:29:08 volumio sudo[2477]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:29:08 volumio volumio[1239]: info: PeppyMeterBasic ---peppymeterbasic status stop May 29 08:29:08 volumio sudo[2479]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service May 29 08:29:08 volumio sudo[2479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:29:08 volumio sudo[2482]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service May 29 08:29:08 volumio sudo[2482]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:29:08 volumio go-librespot[2144]: time="2025-05-29T08:29:08+03:00" level=debug msg="resolved context of track" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:08 volumio go-librespot[2144]: time="2025-05-29T08:29:08+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:08 volumio go-librespot[2144]: time="2025-05-29T08:29:08+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:08 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:29:08 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:29:08 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:29:08 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:29:08 volumio sudo[2485]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service May 29 08:29:08 volumio sudo[2485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:29:08 volumio systemd[1]: peppymeterbasic.service: Deactivated successfully. May 29 08:29:08 volumio systemd[1]: Stopped peppymeterbasic.service - peppymeterbasic Daemon. May 29 08:29:08 volumio systemd[1]: peppymeterbasic.service: Consumed 1.258s CPU time. May 29 08:29:08 volumio sudo[2479]: pam_unix(sudo:session): session closed for user root May 29 08:29:08 volumio volumio[1239]: info: peppymeterbasic Daemon Stop May 29 08:29:08 volumio sudo[2477]: pam_unix(sudo:session): session closed for user root May 29 08:29:08 volumio volumio[1239]: info: peppymeterbasic Daemon Stop May 29 08:29:08 volumio sudo[2482]: pam_unix(sudo:session): session closed for user root May 29 08:29:08 volumio volumio[1239]: info: peppymeterbasic Daemon Stop May 29 08:29:08 volumio sudo[2472]: pam_unix(sudo:session): session closed for user root May 29 08:29:08 volumio volumio[1239]: info: peppymeterbasic Daemon Stop May 29 08:29:08 volumio sudo[2485]: pam_unix(sudo:session): session closed for user root May 29 08:29:08 volumio volumio[1239]: info: peppymeterbasic Daemon Stop May 29 08:29:08 volumio go-librespot[2144]: time="2025-05-29T08:29:08+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:29:08 volumio go-librespot[2144]: time="2025-05-29T08:29:08+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:29:08 volumio volumio[1239]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1izTPgfFEyvc0hl7uYAzGt","play_origin":"go-librespot"}} May 29 08:29:09 volumio go-librespot[2144]: time="2025-05-29T08:29:09+03:00" level=debug msg="selected format OGG_VORBIS_320 (24db08dfda8040abb78a5e7eba406dae3bf0263f)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:09 volumio go-librespot[2144]: time="2025-05-29T08:29:09+03:00" level=debug msg="requested aes key for file 24db08dfda8040abb78a5e7eba406dae3bf0263f, gid: 1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:09 volumio go-librespot[2144]: time="2025-05-29T08:29:09+03:00" level=debug msg="fetched first chunk of 31, total size is 15836880 bytes" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:09 volumio go-librespot[2144]: time="2025-05-29T08:29:09+03:00" level=debug msg="created new output device" May 29 08:29:09 volumio go-librespot[2144]: time="2025-05-29T08:29:09+03: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" May 29 08:29:09 volumio go-librespot[2144]: time="2025-05-29T08:29:09+03:00" level=info msg="loaded track \"A Thousand Kisses Deep\" (paused: false, position: 0ms, duration: 385333ms, prefetched: false)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:09 volumio go-librespot[2144]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:29:09 volumio go-librespot[2143]: Aborted May 29 08:29:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:29:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:29:09 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:29:09 volumio volumio[1239]: info: Connection to go-librespot Websocket closed May 29 08:29:11 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:11 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:11 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:11 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:11 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:11 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:11 volumio volumio[1239]: info: [1748496551902] ControllerSpotify::clearAddPlayTrack May 29 08:29:11 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:11 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:29:12 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:29:12 volumio volumio[1239]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:29:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. May 29 08:29:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:29:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:29:12 volumio go-librespot[2490]: go-librespot daemon starting... May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="app state loaded" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=info msg="zeroconf server listening on port 44589" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="obtained new client token: AABGMxlEtNyh1aL4F/3A5VJbcJw5TVMKNZTN8bgGWypfilpAukQMMSFLmjAvJXzoqwry+ZBB6GAKi6ICXgAn9P3GddHfdYRBoDMgqaacSbui62uLRL1/UJJeofWhDorrcyU6T6SvEfUM39wP/tI3qslMr67SdcAUdSGVR7VcZrd5GORijPJhJZhTO7FaWbNzOsYyr/iVbtSDU2cNoYbdJtUbwrPt+cVL19TSpar6aqNRYwHIurT5auw=" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="completed keyexchange" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="completed challenge" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:29:12 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:12 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:12 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:12 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:12 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:12 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:12 volumio volumio[1239]: info: [1748496552938] ControllerSpotify::clearAddPlayTrack May 29 08:29:12 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:29:12 volumio go-librespot[2491]: time="2025-05-29T08:29:12+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=debug msg="dealer connection opened" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=trace msg="starting dealer recv loop" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=trace msg="received accesspoint ping" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=debug msg="resolved context of track" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:13 volumio go-librespot[2491]: time="2025-05-29T08:29:13+03:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" May 29 08:29:13 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:13 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:13 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:13 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:13 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:13 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:13 volumio volumio[1239]: info: [1748496553895] ControllerSpotify::clearAddPlayTrack May 29 08:29:13 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:14 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:14 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:14 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:14 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:14 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:14 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:14 volumio volumio[1239]: info: [1748496554096] ControllerSpotify::clearAddPlayTrack May 29 08:29:14 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:14 volumio go-librespot[2491]: time="2025-05-29T08:29:14+03:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" May 29 08:29:15 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:29:15 volumio go-librespot[2491]: time="2025-05-29T08:29:15+03:00" level=debug msg="new websocket client" May 29 08:29:15 volumio volumio[1239]: info: Connection to go-librespot Websocket established May 29 08:29:15 volumio go-librespot[2491]: time="2025-05-29T08:29:15+03:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" May 29 08:29:15 volumio go-librespot[2491]: time="2025-05-29T08:29:15+03:00" level=error msg="failed put state after update" error="put state request failed with status 400: Require at least one of callback url or connection id" May 29 08:29:15 volumio go-librespot[2491]: time="2025-05-29T08:29:15+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:29:15 volumio volumio[1239]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1izTPgfFEyvc0hl7uYAzGt","play_origin":"go-librespot"}} May 29 08:29:15 volumio go-librespot[2491]: time="2025-05-29T08:29:15+03:00" level=debug msg="selected format OGG_VORBIS_320 (24db08dfda8040abb78a5e7eba406dae3bf0263f)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:15 volumio go-librespot[2491]: time="2025-05-29T08:29:15+03:00" level=debug msg="requested aes key for file 24db08dfda8040abb78a5e7eba406dae3bf0263f, gid: 1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:18 volumio volumio[1239]: info: Getting Spotify volume May 29 08:29:18 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 May 29 08:29:18 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:29:18 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:18 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:29:19 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. May 29 08:29:22 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:29:22 volumio volumio[1239]: info: In handleBrowseUri, curUri=spotify May 29 08:29:22 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:22 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:22 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:22 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:25 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:25 volumio volumio[1239]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:29:25 volumio volumio[1239]: info: CoreStateMachine::ClearQueue May 29 08:29:25 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:25 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:25 volumio volumio[1239]: info: CorePlayQueue::clearPlayQueue May 29 08:29:25 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:25 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:25 volumio volumio[1239]: info: CoreStateMachine::addQueueItems May 29 08:29:25 volumio volumio[1239]: info: CorePlayQueue::addQueueItems May 29 08:29:25 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:25 volumio volumio[1239]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DXcU2mDfNlJqd May 29 08:29:25 volumio volumio[1239]: info: Exploding uri spotify:playlist:37i9dQZF1DXcU2mDfNlJqd in service spop May 29 08:29:25 volumio volumio[1239]: SPOTIFY: EXPLODING URI:spotify:playlist:37i9dQZF1DXcU2mDfNlJqd May 29 08:29:26 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:26 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:26 volumio volumio[1239]: info: CoreStateMachine::updateTrackBlock May 29 08:29:26 volumio volumio[1239]: info: CorePlayQueue::getTrackBlock May 29 08:29:26 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:26 volumio volumio[1239]: info: CoreStateMachine::play index 0 May 29 08:29:26 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:26 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:26 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:26 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:26 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:26 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:26 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:26 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:26 volumio volumio[1239]: info: [1748496566370] ControllerSpotify::clearAddPlayTrack May 29 08:29:26 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:27 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:27 volumio volumio[1239]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:29:27 volumio volumio[1239]: info: CoreStateMachine::ClearQueue May 29 08:29:27 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:27 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:27 volumio volumio[1239]: info: CorePlayQueue::clearPlayQueue May 29 08:29:27 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:27 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:27 volumio volumio[1239]: info: CoreStateMachine::addQueueItems May 29 08:29:27 volumio volumio[1239]: info: CorePlayQueue::addQueueItems May 29 08:29:27 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:27 volumio volumio[1239]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:27 volumio volumio[1239]: info: Exploding uri spotify:playlist:37i9dQZF1DX1V3tM4cuX0v in service spop May 29 08:29:27 volumio volumio[1239]: SPOTIFY: EXPLODING URI:spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:28 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::updateTrackBlock May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::getTrackBlock May 29 08:29:28 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::play index 0 May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:28 volumio volumio[1239]: info: [1748496568037] ControllerSpotify::clearAddPlayTrack May 29 08:29:28 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:28 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:28 volumio volumio[1239]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::ClearQueue May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::clearPlayQueue May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:28 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::addQueueItems May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::addQueueItems May 29 08:29:28 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:28 volumio volumio[1239]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:28 volumio volumio[1239]: info: Using cached record of: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:28 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::updateTrackBlock May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::getTrackBlock May 29 08:29:28 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::play index 0 May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:28 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:28 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:28 volumio volumio[1239]: info: [1748496568461] ControllerSpotify::clearAddPlayTrack May 29 08:29:28 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:29 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::ClearQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::clearPlayQueue May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::addQueueItems May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::addQueueItems May 29 08:29:29 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:29 volumio volumio[1239]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:29 volumio volumio[1239]: info: Using cached record of: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::updateTrackBlock May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrackBlock May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::play index 0 May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:29 volumio volumio[1239]: info: [1748496569156] ControllerSpotify::clearAddPlayTrack May 29 08:29:29 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:29 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::ClearQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::clearPlayQueue May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::addQueueItems May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::addQueueItems May 29 08:29:29 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:29 volumio volumio[1239]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:29 volumio volumio[1239]: info: Using cached record of: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::updateTrackBlock May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrackBlock May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::play index 0 May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:29 volumio volumio[1239]: info: [1748496569719] ControllerSpotify::clearAddPlayTrack May 29 08:29:29 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:29 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::ClearQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::clearPlayQueue May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::addQueueItems May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::addQueueItems May 29 08:29:29 volumio volumio[1239]: info: Preload queue cleared May 29 08:29:29 volumio volumio[1239]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:29 volumio volumio[1239]: info: Using cached record of: spotify:playlist:37i9dQZF1DX1V3tM4cuX0v May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPushQueue May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::saveQueue May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::updateTrackBlock May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrackBlock May 29 08:29:29 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::play index 0 May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:29 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:29 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:29 volumio volumio[1239]: info: [1748496569996] ControllerSpotify::clearAddPlayTrack May 29 08:29:29 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=debug msg="received connection id: MTA2YTczMGEtNGJiMC00MWNkLWIyYjItZTFiMjcxOGMzNzNjK2RlYWxlcit0Y3A6Ly8wYWNhNDBmZC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArRDZEN0UyM0VBMzFFMDcyMTY1NTc0QkY2RDlBOTdGRTBBRDY0MzhDM0Q1Qzg1RUQ3RkM0MTRCMEU1NDFBOUZFMQ==" May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1izTPgfFEyvc0hl7uYAzGt: failed retrieving audio key: context deadline exceeded" May 29 08:29:30 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=debug msg="resolved context of track" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:29:30 volumio volumio[1239]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1izTPgfFEyvc0hl7uYAzGt","play_origin":"go-librespot"}} May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=debug msg="selected format OGG_VORBIS_320 (24db08dfda8040abb78a5e7eba406dae3bf0263f)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:30 volumio go-librespot[2491]: time="2025-05-29T08:29:30+03:00" level=debug msg="requested aes key for file 24db08dfda8040abb78a5e7eba406dae3bf0263f, gid: 1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:32 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:29:32 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:36 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:36 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:36 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:36 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:36 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:36 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:36 volumio volumio[1239]: info: [1748496576973] ControllerSpotify::clearAddPlayTrack May 29 08:29:36 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:40 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:40 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:40 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:40 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:40 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:40 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 May 29 08:29:40 volumio volumio[1239]: info: [1748496580431] ControllerSpotify::clearAddPlayTrack May 29 08:29:40 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:43 volumio go-librespot[2491]: time="2025-05-29T08:29:43+03:00" level=trace msg="sent dealer ping" May 29 08:29:43 volumio go-librespot[2491]: time="2025-05-29T08:29:43+03:00" level=trace msg="received dealer pong" May 29 08:29:45 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:45 volumio volumio[1239]: info: CoreStateMachine::play index 1 May 29 08:29:45 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:45 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:45 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:45 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:45 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:45 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:45 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:45 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:45 volumio volumio[1239]: info: [1748496585585] ControllerSpotify::clearAddPlayTrack May 29 08:29:45 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:45 volumio go-librespot[2491]: time="2025-05-29T08:29:45+03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1izTPgfFEyvc0hl7uYAzGt: failed retrieving audio key: context deadline exceeded" May 29 08:29:45 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 29 08:29:45 volumio go-librespot[2491]: time="2025-05-29T08:29:45+03:00" level=debug msg="resolved context of track" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:45 volumio go-librespot[2491]: time="2025-05-29T08:29:45+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:45 volumio go-librespot[2491]: time="2025-05-29T08:29:45+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:45 volumio go-librespot[2491]: time="2025-05-29T08:29:45+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:29:45 volumio go-librespot[2491]: time="2025-05-29T08:29:45+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:29:45 volumio volumio[1239]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1izTPgfFEyvc0hl7uYAzGt","play_origin":"go-librespot"}} May 29 08:29:45 volumio go-librespot[2491]: time="2025-05-29T08:29:45+03:00" level=debug msg="selected format OGG_VORBIS_320 (24db08dfda8040abb78a5e7eba406dae3bf0263f)" uri="spotify:track:1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:45 volumio go-librespot[2491]: time="2025-05-29T08:29:45+03:00" level=debug msg="requested aes key for file 24db08dfda8040abb78a5e7eba406dae3bf0263f, gid: 1izTPgfFEyvc0hl7uYAzGt" May 29 08:29:46 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:46 volumio volumio[1239]: info: CoreStateMachine::play index 1 May 29 08:29:46 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:46 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:46 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:46 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:46 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:46 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:46 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:46 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:46 volumio volumio[1239]: info: [1748496586983] ControllerSpotify::clearAddPlayTrack May 29 08:29:46 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:47 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::play index 1 May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:47 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:47 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:47 volumio volumio[1239]: info: [1748496587713] ControllerSpotify::clearAddPlayTrack May 29 08:29:47 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:47 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::play index 1 May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::stop May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:29:47 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:47 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:29:47 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:47 volumio volumio[1239]: info: [1748496587917] ControllerSpotify::clearAddPlayTrack May 29 08:29:47 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:29:51 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:29:51 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:29:56 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 29 08:29:56 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 29 08:29:57 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. May 29 08:29:57 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... May 29 08:29:57 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 29 08:29:57 volumio systemd[1]: welcome.service: Deactivated successfully. May 29 08:29:57 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. May 29 08:29:57 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... May 29 08:29:57 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... May 29 08:29:57 volumio welcome[2576]: Resolved ip:[3] 192.168.0.193 192.168.211.1 169.254.70.24 May 29 08:29:57 volumio dbus-daemon[817]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.28' (uid=0 pid=2577 comm="timedatectl show --property=NTPSynchronized --valu") May 29 08:29:57 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. May 29 08:29:57 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. May 29 08:29:57 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 29 08:29:57 volumio dbus-daemon[817]: [system] Successfully activated service 'org.freedesktop.timedate1' May 29 08:29:57 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. May 29 08:29:57 volumio setdatetime-helper.sh[2569]: Time is not synchronized. Attempting to sync... May 29 08:29:57 volumio sudo[2589]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 29 May 2025 05:29:57 GMT#015' May 29 08:29:57 volumio sudo[2589]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 29 08:29:57 volumio setdatetime-helper.sh[2590]: Thu May 29 08:29:57 EEST 2025 May 29 08:29:57 volumio systemd-journald[502]: Time jumped backwards, rotating. May 29 08:29:57 volumio setdatetime-helper.sh[2569]: Time synchronized successfully. May 29 08:29:57 volumio sudo[2589]: pam_unix(sudo:session): session closed for user root May 29 08:29:57 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 29 08:29:57 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1izTPgfFEyvc0hl7uYAzGt: failed retrieving audio key: context deadline exceeded" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=trace msg="received accesspoint pong ack" May 29 08:30:00 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 29 08:30:00 volumio volumio[1239]: info: Spotify volume: 100 May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=debug msg="resolved context of track" uri="spotify:track:4J7GqAqdOfYrcOKJIp4m8U" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4J7GqAqdOfYrcOKJIp4m8U" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:4J7GqAqdOfYrcOKJIp4m8U" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:30:00 volumio volumio[1239]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4J7GqAqdOfYrcOKJIp4m8U","play_origin":"go-librespot"}} May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=debug msg="selected format OGG_VORBIS_320 (675519853218b31e9f9c7633f0b8f64160732188)" uri="spotify:track:4J7GqAqdOfYrcOKJIp4m8U" May 29 08:30:00 volumio go-librespot[2491]: time="2025-05-29T08:30:00+03:00" level=debug msg="requested aes key for file 675519853218b31e9f9c7633f0b8f64160732188, gid: 4J7GqAqdOfYrcOKJIp4m8U" May 29 08:30:01 volumio go-librespot[2491]: time="2025-05-29T08:30:01+03:00" level=debug msg="fetched first chunk of 11, total size is 5430660 bytes" uri="spotify:track:4J7GqAqdOfYrcOKJIp4m8U" May 29 08:30:01 volumio go-librespot[2491]: time="2025-05-29T08:30:01+03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:4J7GqAqdOfYrcOKJIp4m8U" May 29 08:30:01 volumio go-librespot[2491]: time="2025-05-29T08:30:01+03:00" level=debug msg="created new output device" May 29 08:30:01 volumio go-librespot[2491]: time="2025-05-29T08:30:01+03: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" May 29 08:30:01 volumio go-librespot[2491]: time="2025-05-29T08:30:01+03:00" level=info msg="loaded track \"Зірочка палай\" (paused: false, position: 1ms, duration: 128640ms, prefetched: false)" uri="spotify:track:4J7GqAqdOfYrcOKJIp4m8U" May 29 08:30:01 volumio go-librespot[2491]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio go-librespot[2490]: Aborted May 29 08:30:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:01 volumio volumio[1239]: info: Connection to go-librespot Websocket closed May 29 08:30:03 volumio volumio[1239]: info: CoreCommandRouter::getUIConfigOnPlugin May 29 08:30:04 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:30:04 volumio volumio[1239]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:30:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. May 29 08:30:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:04 volumio go-librespot[2611]: go-librespot daemon starting... May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="app state loaded" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=info msg="zeroconf server listening on port 36875" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="obtained new client token: AACcvLzL0GujeEDipf6JYJi+vSmGPslkw+Fvm5XOarR2IVsoL9ygcCvhVvkChtJ76o07Fg0lcnqSjliLDl7M6PI/uc1b6ALXvcbTG4abtoo/zWw7zdggQ8L8HVtXcfaAhRLiygYPHS9p/H0Y9k8I4tZacdcZboKU6GvXXo+tMYap1r//erHijkA/N4I3RrmtTIFOHRIHV6ZccWaLHnrFxDUoomfXxHAJBsvlz4b3wEXCnYi6ot+apxM=" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="completed keyexchange" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="completed challenge" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="dealer connection opened" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=trace msg="starting dealer recv loop" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=trace msg="received accesspoint ping" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:30:04 volumio go-librespot[2612]: time="2025-05-29T08:30:04+03:00" level=debug msg="received connection id: ZWRiMWNlYjAtM2U2Zi00YzRhLThlMDItYmVhZWE2YjQzMGQ1K2RlYWxlcit0Y3A6Ly8wYWNhNDIwNS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQzNEMDVENTlGRTg5MzRDOTE1NjVDREFGMDM5NTdEN0Y4RUZDNzVFODk5MkU2MzVGQTExNjM5MjlERjA4NzA1NQ==" May 29 08:30:05 volumio go-librespot[2612]: time="2025-05-29T08:30:05+03:00" level=trace msg="received accesspoint pong ack" May 29 08:30:05 volumio go-librespot[2612]: time="2025-05-29T08:30:05+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:30:07 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:30:07 volumio go-librespot[2612]: time="2025-05-29T08:30:07+03:00" level=debug msg="new websocket client" May 29 08:30:07 volumio volumio[1239]: info: Connection to go-librespot Websocket established May 29 08:30:10 volumio volumio[1239]: info: Getting Spotify volume May 29 08:30:10 volumio volumio[1239]: info: Spotify volume: 100 May 29 08:30:10 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 May 29 08:30:10 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:10 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:10 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:30:22 volumio volumio[1239]: info: CALLMETHOD: music_service spop logout May 29 08:30:22 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , logout May 29 08:30:22 volumio volumio[1239]: info: Deleting Spotify credentials File May 29 08:30:22 volumio volumio[1239]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify May 29 08:30:22 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 08:30:22 volumio volumio[1239]: Cannot find translation for source YouTube2 May 29 08:30:22 volumio volumio[1239]: Cannot find translation for source YouTube Music May 29 08:30:23 volumio volumio[1239]: info: Creating Spotify config file May 29 08:30:23 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:30:23 volumio volumio[1239]: info: Spotify config file written May 29 08:30:24 volumio sudo[2648]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 08:30:24 volumio sudo[2648]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:30:24 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 29 08:30:24 volumio systemd[1]: go-librespot-daemon.service: Killing process 2613 (go-librespot) with signal SIGKILL. May 29 08:30:24 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 29 08:30:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:24 volumio volumio[1239]: info: Connection to go-librespot Websocket closed May 29 08:30:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:24 volumio go-librespot[2650]: go-librespot daemon starting... May 29 08:30:24 volumio sudo[2648]: pam_unix(sudo:session): session closed for user root May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=debug msg="no app state found" May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=debug msg="stored credentials not found" May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=info msg="generated new device id: d6e9c31b2b57cf5687cdf9c10ed7e7c7431e90ad" May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:30:24 volumio go-librespot[2652]: time="2025-05-29T08:30:24+03:00" level=info msg="zeroconf server listening on port 37147" May 29 08:30:26 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. May 29 08:30:27 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:30:27 volumio go-librespot[2652]: time="2025-05-29T08:30:27+03:00" level=debug msg="new websocket client" May 29 08:30:27 volumio volumio[1239]: info: Connection to go-librespot Websocket established May 29 08:30:27 volumio volumio[1239]: info: go-librespot daemon successfully initialized May 29 08:30:30 volumio volumio[1239]: info: Getting Spotify volume May 29 08:30:30 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 May 29 08:30:30 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:30 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:30 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:30:30 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:30:30 volumio go-librespot[2652]: time="2025-05-29T08:30:30+03:00" level=debug msg="new websocket client" May 29 08:30:30 volumio volumio[1239]: info: Connection to go-librespot Websocket established May 29 08:30:33 volumio volumio[1239]: info: Getting Spotify volume May 29 08:30:33 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 May 29 08:30:33 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:33 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:33 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:30:39 volumio volumio[1239]: info: Received OAUTH Data May 29 08:30:39 volumio volumio[1239]: info: Executing Spotify Oauth Login May 29 08:30:39 volumio volumio[1239]: info: Saving Spotify Refresh Token May 29 08:30:39 volumio sudo[2691]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 08:30:39 volumio sudo[2691]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:30:39 volumio sudo[2693]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 08:30:39 volumio sudo[2693]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:30:39 volumio sudo[2691]: pam_unix(sudo:session): session closed for user root May 29 08:30:39 volumio sudo[2693]: pam_unix(sudo:session): session closed for user root May 29 08:30:39 volumio volumio[1239]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 08:30:39 volumio volumio[1239]: SPOTIFY: BQCGZC3fUA7FrJFEQ2U6lzzKyIHT6wHH4T-_IN7r_kMMoElm4iWTDj-P3VViwZB_Cj9LQqD3Wf_0hQBpnnXEN_I-ZPpnS0rIJxIRZtWFQKlk9njBlCjvnXjtoFjRyXhFyiN0e1eM0JaQ18HmLnjqStXZaKkQmvsKMXIdSei9MGSuGXzmOimI8CFusuSfMawQLVWk-ouReqB4QnxVmFkHsIT77C8cfkVEuwHePEYjB85o5WNjBoH6S26g6PAapWrfJAqJzehJ5oQCKa7Gpmxk6W5JdQfwaqzCDVqd8L-69E-N6d4 May 29 08:30:39 volumio volumio[1239]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 08:30:39 volumio volumio[1239]: info: New Spotify access token = BQCGZC3fUA7FrJFEQ2U6lzzKyIHT6wHH4T-_IN7r_kMMoElm4iWTDj-P3VViwZB_Cj9LQqD3Wf_0hQBpnnXEN_I-ZPpnS0rIJxIRZtWFQKlk9njBlCjvnXjtoFjRyXhFyiN0e1eM0JaQ18HmLnjqStXZaKkQmvsKMXIdSei9MGSuGXzmOimI8CFusuSfMawQLVWk-ouReqB4QnxVmFkHsIT77C8cfkVEuwHePEYjB85o5WNjBoH6S26g6PAapWrfJAqJzehJ5oQCKa7Gpmxk6W5JdQfwaqzCDVqd8L-69E-N6d4 May 29 08:30:39 volumio volumio[1239]: info: Spotify credentials grant success - running version from March 24, 2019 May 29 08:30:39 volumio volumio[1239]: verbose: New Socket.io Connection to 192.168.0.193 from 192.168.0.183 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::volumioGetVisibleSources May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:39 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::getUIConfigOnPlugin May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 29 08:30:39 volumio volumio[1239]: info: Received Get System Info May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:30:39 volumio volumio[1239]: info: Discovery: Getting this device information May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:39 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:39 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:39 volumio volumio[1239]: info: Listing playlists May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 08:30:39 volumio volumio[1239]: SPOTIFY: User informations: {"country":"UA","display_name":"Igor","email":"ihhorm@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/pb5pp9zr5gss9vfrrdysusbut"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/pb5pp9zr5gss9vfrrdysusbut","id":"pb5pp9zr5gss9vfrrdysusbut","images":[],"product":"premium","type":"user","uri":"spotify:user:pb5pp9zr5gss9vfrrdysusbut"} May 29 08:30:39 volumio volumio[1239]: info: Creating Spotify config file May 29 08:30:39 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:30:39 volumio volumio[1239]: info: Spotify config file written May 29 08:30:39 volumio sudo[2697]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 08:30:39 volumio sudo[2697]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:30:39 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 29 08:30:40 volumio systemd[1]: go-librespot-daemon.service: Killing process 2657 (go-librespot) with signal SIGKILL. May 29 08:30:40 volumio volumio[1239]: info: Connection to go-librespot Websocket closed May 29 08:30:40 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 29 08:30:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:40 volumio volumio[1239]: info: Connection to go-librespot Websocket closed May 29 08:30:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:40 volumio go-librespot[2700]: go-librespot daemon starting... May 29 08:30:40 volumio sudo[2697]: pam_unix(sudo:session): session closed for user root May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="app state loaded" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="stored credentials not found" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:30:40 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=info msg="zeroconf server listening on port 38155" May 29 08:30:40 volumio volumio[1239]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 08:30:40 volumio volumio[1239]: SPOTIFY: BQCVPIoU6GlkgSUwNMzH08K85JZiP5ie72VSIbitouLlOLMCWbw58oFR_8Cw03zArYB5H5Ejml6m7URqmbGsBIOKU-aCM5e223kwZldvuSJsHuI_4YyMlIvi1a0LmYLImuaPWHwnBhkPLvd4iutG2ZFAWm7FCkgRvekXaHJylWgSQBswTIHaC-NgoSqEu4v0UrKMrVdg70-RRHighgUPNt1ZbPCHe0RrlXLv3L5BF-7yJbZ1ZQK8PFG353XV2tYb0ireqZ3NX6Io2ltOWMjtxBZ8pCIiGtUaM6aJSasnz0TllgA May 29 08:30:40 volumio volumio[1239]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 08:30:40 volumio volumio[1239]: info: New Spotify access token = BQCVPIoU6GlkgSUwNMzH08K85JZiP5ie72VSIbitouLlOLMCWbw58oFR_8Cw03zArYB5H5Ejml6m7URqmbGsBIOKU-aCM5e223kwZldvuSJsHuI_4YyMlIvi1a0LmYLImuaPWHwnBhkPLvd4iutG2ZFAWm7FCkgRvekXaHJylWgSQBswTIHaC-NgoSqEu4v0UrKMrVdg70-RRHighgUPNt1ZbPCHe0RrlXLv3L5BF-7yJbZ1ZQK8PFG353XV2tYb0ireqZ3NX6Io2ltOWMjtxBZ8pCIiGtUaM6aJSasnz0TllgA May 29 08:30:40 volumio volumio[1239]: info: Spotify credentials grant success - running version from March 24, 2019 May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="obtained new client token: AACaT70yCftN3op4o6RsbP91w41GzgRsPlEw+l+3ooQT8hSS+5za8mIjXG7ULzqdSJFbD8k2W2o6T/hzYG1/TEurVEBgsN5UNnu48OD724Uxjb+DUTsizwh3pSOoOG6BBYGFQFa48ECuhgB7Lbr/j6Q3bwTCuW4vEniyQrDfXxMqguIfG6pSNaBjn1/3o/5Ih5A8VC6M6oAFz6sE+qspIb3CI9/4NUO03y7DQFiIgjo625L33wbf" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:30:40 volumio volumio[1239]: SPOTIFY: User informations: {"country":"UA","display_name":"Igor","email":"ihhorm@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/pb5pp9zr5gss9vfrrdysusbut"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/pb5pp9zr5gss9vfrrdysusbut","id":"pb5pp9zr5gss9vfrrdysusbut","images":[],"product":"premium","type":"user","uri":"spotify:user:pb5pp9zr5gss9vfrrdysusbut"} May 29 08:30:40 volumio volumio[1239]: info: Spotify Successfully logged in May 29 08:30:40 volumio volumio[1239]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 29 08:30:40 volumio volumio[1239]: info: [1748496640395] CoreMusicLibrary::Adding element Spotify May 29 08:30:40 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 08:30:40 volumio volumio[1239]: Cannot find translation for source YouTube2 May 29 08:30:40 volumio volumio[1239]: Cannot find translation for source YouTube Music May 29 08:30:40 volumio volumio[1239]: Cannot find translation for source Spotify May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="completed keyexchange" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="completed challenge" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="stored credentials for pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="dealer connection opened" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=trace msg="starting dealer recv loop" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=trace msg="received accesspoint ping" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="received connection id: ZGRiMWMwMjAtMzk1Zi00MzRkLTk3ZmEtMjVkYmIyZWY4ZmNmK2RlYWxlcit0Y3A6Ly8wYWNhNDBhYS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMTBFNjY1OTUxRTI2QUJBRkQzQzRFOEVDNjhCOTU0RkNGRkY1NkI2QjZCQkVCM0E4Rjg5MEFCNTc2Q0Y3Mjc2RQ==" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=trace msg="received accesspoint pong ack" May 29 08:30:40 volumio go-librespot[2701]: time="2025-05-29T08:30:40+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:30:41 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 29 08:30:41 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 29 08:30:41 volumio volumio[1239]: info: Received Get System Info May 29 08:30:41 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:30:41 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:30:41 volumio volumio[1239]: info: Discovery: Getting this device information May 29 08:30:41 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:41 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:41 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:30:42 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 29 08:30:42 volumio volumio[1239]: info: Received Get System Info May 29 08:30:42 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:30:42 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:30:42 volumio volumio[1239]: info: Discovery: Getting this device information May 29 08:30:42 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:42 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:42 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:30:43 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:30:43 volumio go-librespot[2701]: time="2025-05-29T08:30:43+03:00" level=debug msg="new websocket client" May 29 08:30:43 volumio volumio[1239]: info: Connection to go-librespot Websocket established May 29 08:30:43 volumio volumio[1239]: info: go-librespot daemon successfully initialized May 29 08:30:46 volumio volumio[1239]: info: Getting Spotify volume May 29 08:30:46 volumio volumio[1239]: info: Spotify volume: 100 May 29 08:30:46 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 May 29 08:30:46 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:46 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:46 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:30:46 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:30:46 volumio go-librespot[2701]: time="2025-05-29T08:30:46+03:00" level=debug msg="new websocket client" May 29 08:30:46 volumio volumio[1239]: info: Connection to go-librespot Websocket established May 29 08:30:49 volumio volumio[1239]: info: Getting Spotify volume May 29 08:30:49 volumio volumio[1239]: info: Spotify volume: 100 May 29 08:30:49 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 May 29 08:30:49 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState May 29 08:30:49 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:49 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:30:49 volumio volumio[1239]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 29 08:30:49 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 29 08:30:49 volumio volumio[1239]: info: Creating Spotify config file May 29 08:30:49 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:30:49 volumio volumio[1239]: info: Spotify config file written May 29 08:30:49 volumio sudo[2725]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 08:30:49 volumio sudo[2725]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:30:49 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 29 08:30:49 volumio systemd[1]: go-librespot-daemon.service: Killing process 2704 (go-librespot) with signal SIGKILL. May 29 08:30:49 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 29 08:30:49 volumio volumio[1239]: info: Connection to go-librespot Websocket closed May 29 08:30:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:49 volumio volumio[1239]: info: Connection to go-librespot Websocket closed May 29 08:30:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:49 volumio go-librespot[2727]: go-librespot daemon starting... May 29 08:30:49 volumio sudo[2725]: pam_unix(sudo:session): session closed for user root May 29 08:30:49 volumio go-librespot[2728]: time="2025-05-29T08:30:49+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:30:49 volumio go-librespot[2728]: time="2025-05-29T08:30:49+03:00" level=debug msg="app state loaded" May 29 08:30:49 volumio go-librespot[2728]: time="2025-05-29T08:30:49+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:30:49 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:30:49 volumio go-librespot[2728]: time="2025-05-29T08:30:49+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:30:49 volumio go-librespot[2728]: time="2025-05-29T08:30:49+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:30:49 volumio go-librespot[2728]: time="2025-05-29T08:30:49+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:30:49 volumio go-librespot[2728]: time="2025-05-29T08:30:49+03:00" level=info msg="zeroconf server listening on port 45859" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="obtained new client token: AAAKMOvSAwPawJBgUtdrKRepFF0+zdKHRBnUGbuWUaS2IW5hO9JrR4LDw/UZl+HyHKRCq7qYf0vAZLqYVRrpPZAPsQsScmgGlyo+cBbKDf/4FrWvGS7fv5ZBiQ1TAjr2zDjDOhvHyIjQBoSZJISk6lbvAHQi1rRtMD4HKQVZ+gHJtIQxnMaf2+i1G7x0xnwzBgiOLHs3cfnAend56MIZCAuQwoEH24uEYZgDGbnTHscwNvm5Bm4lfaQ=" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="completed keyexchange" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="completed challenge" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="dealer connection opened" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=trace msg="starting dealer recv loop" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=trace msg="received accesspoint ping" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=debug msg="received connection id: NTNmNDYyZDUtNDJlOC00ZjIyLWEwNzItMjBmYjI4NjZkOTlkK2RlYWxlcit0Y3A6Ly8wYWNhNDFlZS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMkMzMUUzMUI4NzM0MjJENDRCMzAxM0ZEMjYwMUMzOUNDNEE2MzhBNzAxQjQzMDc2Q0JCODk5QkIyOTQzQTQzOQ==" May 29 08:30:50 volumio go-librespot[2728]: time="2025-05-29T08:30:50+03:00" level=trace msg="received accesspoint pong ack" May 29 08:30:50 volumio volumio[1239]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 29 08:30:50 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 29 08:30:50 volumio volumio[1239]: info: Creating Spotify config file May 29 08:30:50 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:30:50 volumio volumio[1239]: info: Spotify config file written May 29 08:30:50 volumio sudo[2736]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 08:30:50 volumio sudo[2736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:30:50 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 29 08:30:50 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 29 08:30:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:30:50 volumio sudo[2736]: pam_unix(sudo:session): session closed for user root May 29 08:30:50 volumio go-librespot[2738]: go-librespot daemon starting... May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=debug msg="app state loaded" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=info msg="zeroconf server listening on port 43583" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=debug msg="obtained new client token: AAAb3DW9uOEfrgxIkqVzzrWWXn0hx7f2nUdDTLzc4IcsYw3JeIx9Wty0oH2Nc9o6n2VtByfqqc6UC0xDz2mP9t0vak2yiNMiz2+ZYsa/usWrfo8OBhDWpvLfDPAjVvypfqVVi1uKekrrLNqdbvDE1g4fgjqmKp3kvEIyStSNkxjjEiEtHUleuNVOy083FsTiNfZ27Cvp2HQM6knrrEsTtLXbwfKQLAbM6yu1Ma5aIaBrdfJcmgvph+o=" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=debug msg="completed keyexchange" May 29 08:30:50 volumio go-librespot[2739]: time="2025-05-29T08:30:50+03:00" level=debug msg="completed challenge" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="dealer connection opened" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=trace msg="starting dealer recv loop" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=trace msg="received accesspoint ping" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="received connection id: NzgzZjNjMGYtN2NmNC00NWMyLThkZDgtYjNiMzRmNzc4Njg4K2RlYWxlcit0Y3A6Ly8wYWNhNDIyYi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQjAzNEYzRDVGOUU1MUY2NDUwNzQzMzEyRTIxNjcxRTU1RDQ5NEEzNzQ1OTc3N0EyOUQ2QzAwNDc1NTk3REIwQQ==" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=trace msg="received accesspoint pong ack" May 29 08:30:51 volumio go-librespot[2739]: time="2025-05-29T08:30:51+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:30:52 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket May 29 08:30:52 volumio go-librespot[2739]: time="2025-05-29T08:30:52+03:00" level=debug msg="new websocket client" May 29 08:30:52 volumio volumio[1239]: info: Connection to go-librespot Websocket established May 29 08:30:52 volumio volumio[1239]: info: go-librespot daemon successfully initialized May 29 08:30:53 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:30:53 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:30:53 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:30:53 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:53 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:30:53 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:53 volumio volumio[1239]: info: [1748496653249] ControllerSpotify::clearAddPlayTrack May 29 08:30:53 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="resolved context of track" uri="spotify:track:4PMQ591DnjhGRYZNLETsno" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4PMQ591DnjhGRYZNLETsno" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4PMQ591DnjhGRYZNLETsno" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:30:53 volumio volumio[1239]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4PMQ591DnjhGRYZNLETsno","play_origin":"go-librespot"}} May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="selected format OGG_VORBIS_320 (ebbf782d4f8d6119e19e33fc2effc659da58175a)" uri="spotify:track:4PMQ591DnjhGRYZNLETsno" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="requested aes key for file ebbf782d4f8d6119e19e33fc2effc659da58175a, gid: 4PMQ591DnjhGRYZNLETsno" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1123" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 29 08:30:53 volumio volumio[1239]: info: go-librespot daemon successfully initialized May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="fetched first chunk of 17, total size is 8517550 bytes" uri="spotify:track:4PMQ591DnjhGRYZNLETsno" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=debug msg="created new output device" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03: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" May 29 08:30:53 volumio go-librespot[2739]: time="2025-05-29T08:30:53+03:00" level=info msg="loaded track \"Пінаколада\" (paused: false, position: 0ms, duration: 195784ms, prefetched: false)" uri="spotify:track:4PMQ591DnjhGRYZNLETsno" May 29 08:30:53 volumio go-librespot[2739]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:30:53 volumio go-librespot[2738]: Aborted May 29 08:30:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:30:53 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:30:53 volumio volumio[1239]: info: Connection to go-librespot Websocket closed May 29 08:30:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:30:54 volumio volumio[1239]: info: CoreCommandRouter::volumioPlay May 29 08:30:54 volumio volumio[1239]: info: CoreStateMachine::play index undefined May 29 08:30:54 volumio volumio[1239]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:30:54 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:54 volumio volumio[1239]: info: CoreStateMachine::startPlaybackTimer May 29 08:30:54 volumio volumio[1239]: info: CorePlayQueue::getTrack 1 May 29 08:30:54 volumio volumio[1239]: info: [1748496654157] ControllerSpotify::clearAddPlayTrack May 29 08:30:54 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/play May 29 08:30:54 volumio volumio[1239]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:30:55 volumio volumio[1239]: info: Getting Spotify volume May 29 08:30:55 volumio volumio[1239]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 08:30:55 volumio volumio[1239]: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:30:55 volumio volumio[1239]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { May 29 08:30:55 volumio volumio[1239]: errno: -111, May 29 08:30:55 volumio volumio[1239]: code: 'ECONNREFUSED', May 29 08:30:55 volumio volumio[1239]: syscall: 'connect', May 29 08:30:55 volumio volumio[1239]: address: '127.0.0.1', May 29 08:30:55 volumio volumio[1239]: port: 9879, May 29 08:30:55 volumio volumio[1239]: response: undefined May 29 08:30:55 volumio volumio[1239]: } May 29 08:30:55 volumio volumio[1239]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 08:30:55 volumio sudo[2763]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-05-29 08:29' May 29 08:30:55 volumio sudo[2763]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="fd567ba9bc0dc34c0403e2d5b72a0f46467d1983" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri May 23 07:33:33 UTC 2025" VOLUMIO_VERSION="0.069" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="d67a2da4ffe3f001e986b1f31eaa3a76"