-- Logs begin at Fri 2025-10-31 23:06:12 -03, end at Fri 2025-10-31 23:23:50 -03. -- Oct 31 23:22:00 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 12 Oct 31 23:22:00 volumiobpi volumio[959]: info: VolumeController::SetAlsaVolume26 Oct 31 23:22:00 volumiobpi volumio[959]: info: CoreStateMachine::pushState Oct 31 23:22:00 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 0 Oct 31 23:22:00 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 23:22:00 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushState Oct 31 23:22:00 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 26 Oct 31 23:22:00 volumiobpi volumio[959]: SPOTIFY: SPOTIFY VOLUME 12 Oct 31 23:22:00 volumiobpi volumio[959]: SPOTIFY: VOLUMIO VOLUME 26 Oct 31 23:22:00 volumiobpi volumio[959]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 31 23:22:00 volumiobpi volumio[959]: info: Setting Spotify Volume from Volumio: 26 Oct 31 23:22:02 volumiobpi volumio[959]: info: VolumeController::SetAlsaVolume23 Oct 31 23:22:02 volumiobpi volumio[959]: info: CoreStateMachine::pushState Oct 31 23:22:02 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 0 Oct 31 23:22:02 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 23:22:02 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushState Oct 31 23:22:02 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 23 Oct 31 23:22:02 volumiobpi volumio[959]: SPOTIFY: SPOTIFY VOLUME 26 Oct 31 23:22:02 volumiobpi volumio[959]: SPOTIFY: VOLUMIO VOLUME 23 Oct 31 23:22:02 volumiobpi volumio[959]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 31 23:22:02 volumiobpi volumio[959]: info: Setting Spotify Volume from Volumio: 23 Oct 31 23:22:02 volumiobpi volumio[959]: info: VolumeController::SetAlsaVolume11 Oct 31 23:22:02 volumiobpi volumio[959]: info: CoreStateMachine::pushState Oct 31 23:22:02 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 0 Oct 31 23:22:02 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 23:22:02 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushState Oct 31 23:22:02 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 11 Oct 31 23:22:02 volumiobpi volumio[959]: SPOTIFY: SPOTIFY VOLUME 23 Oct 31 23:22:02 volumiobpi volumio[959]: SPOTIFY: VOLUMIO VOLUME 11 Oct 31 23:22:02 volumiobpi volumio[959]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 31 23:22:02 volumiobpi volumio[959]: info: Setting Spotify Volume from Volumio: 11 Oct 31 23:22:04 volumiobpi volumio[959]: SPOTIFY: SETTING SPOTIFY VOLUME 11 Oct 31 23:22:04 volumiobpi volumio[959]: info: Sending Spotify command with payload to local API: /player/volume Oct 31 23:22:04 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:04-03:00" level=debug msg="update volume requested to 7208/65535" Oct 31 23:22:04 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:04-03:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 31 23:22:04 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:04-03:00" level=trace msg="emitting websocket event: volume" Oct 31 23:22:04 volumiobpi volumio[959]: SPOTIFY: received: {"type":"volume","data":{"value":11,"max":100}} Oct 31 23:22:04 volumiobpi volumio[959]: SPOTIFY: RECEIVED SPOTIFY VOLUME 11 Oct 31 23:22:08 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::ClearQueue Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::stop Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::clearPlayQueue Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::addQueueItems Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::addQueueItems Oct 31 23:22:09 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2lD6W5w72NsrjnKT5HBoCM Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2lD6W5w72NsrjnKT5HBoCM Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1cQygsHlGII3a0H6DmUpA2 Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1cQygsHlGII3a0H6DmUpA2 Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:3Q6OOufAKSKd2P1w0yBuyz Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:3Q6OOufAKSKd2P1w0yBuyz Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2sCAwLNAzfM7duvHoSaUVh Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2sCAwLNAzfM7duvHoSaUVh Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0OMHIc3h1jXfR6V4GKVVAg Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0OMHIc3h1jXfR6V4GKVVAg Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:3qkQzVZYR8pHsqMwyzam30 Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:3qkQzVZYR8pHsqMwyzam30 Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::updateTrackBlock Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::getTrackBlock Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPlay Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::play index 5 Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::addQueueItems Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::addQueueItems Oct 31 23:22:09 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0bbv6aSL5rcjKCu9Aj2Xxa Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0bbv6aSL5rcjKCu9Aj2Xxa Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1tCAJSYysyhQdSsyIGumaA Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1tCAJSYysyhQdSsyIGumaA Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:40ybb9b105RzAhRZB6iRZv Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:40ybb9b105RzAhRZB6iRZv Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6N8J9G7HWoxRzEWFugXAmm Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6N8J9G7HWoxRzEWFugXAmm Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:7h9IAebaWbzqEIDKWFxvNE Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:7h9IAebaWbzqEIDKWFxvNE Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:7DRk0k2Sd2kZL7pXPgM9FH Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:7DRk0k2Sd2kZL7pXPgM9FH Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0bDbepFJBTWgnbcyiIropA Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0bDbepFJBTWgnbcyiIropA Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6KOhAOGfS5n0HwHHEWKuuU Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6KOhAOGfS5n0HwHHEWKuuU Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:4l7tPloKHNLlVR3lHepp25 Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:4l7tPloKHNLlVR3lHepp25 Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2hQI49sxOIXLZjhabjymgn Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2hQI49sxOIXLZjhabjymgn Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6Lo8tzkqE92ccknEaf2tIZ Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6Lo8tzkqE92ccknEaf2tIZ Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2zKRFXwrLZbEHhgiFBWuQj Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2zKRFXwrLZbEHhgiFBWuQj Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1VEBov3sJwl9d1kXlq0tiu Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1VEBov3sJwl9d1kXlq0tiu Oct 31 23:22:09 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6XjqgFFzrmbr4EFfZ7TWqE Oct 31 23:22:09 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6XjqgFFzrmbr4EFfZ7TWqE Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::stop Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::play index undefined Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::updateTrackBlock Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::getTrackBlock Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:09 volumiobpi volumio[959]: info: CoreStateMachine::startPlaybackTimer Oct 31 23:22:09 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:09 volumiobpi volumio[959]: info: [1761963729222] ControllerSpotify::clearAddPlayTrack Oct 31 23:22:09 volumiobpi volumio[959]: info: Sending Spotify command with payload to local API: /player/play Oct 31 23:22:09 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:09-03:00" level=debug msg="resolved context of track" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:09 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:09-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:09 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:09-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:09 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:09-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:22:09 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:09-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 23:22:09 volumiobpi volumio[959]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","play_origin":"go-librespot"}} Oct 31 23:22:09 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:09-03:00" level=debug msg="selected format OGG_VORBIS_320 (7e9061d017b240f955b9b0a32f10d146fca3d2db)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:09 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:09-03:00" level=debug msg="requested aes key for file 7e9061d017b240f955b9b0a32f10d146fca3d2db, gid: 3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 159" Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=debug msg="fetched first chunk of 17, total size is 8456808 bytes" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=trace msg="seek to 1ms (diff: -16ms, samples: 44, bytes: 3764)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:10 volumiobpi go-librespot[1627]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:3qkQzVZYR8pHsqMwyzam30: ALSA error at snd_pcm_open: No such file or directory" Oct 31 23:22:10 volumiobpi volumio[959]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:10 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:10-03:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:10 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 23:22:10 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 23:22:10 volumiobpi volumio[959]: info: Discovery: Getting this device information Oct 31 23:22:10 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:22:10 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:10 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 23:22:11 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::ClearQueue Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::stop Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::clearPlayQueue Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::addQueueItems Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::addQueueItems Oct 31 23:22:11 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2lD6W5w72NsrjnKT5HBoCM Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2lD6W5w72NsrjnKT5HBoCM Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1cQygsHlGII3a0H6DmUpA2 Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1cQygsHlGII3a0H6DmUpA2 Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:3Q6OOufAKSKd2P1w0yBuyz Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:3Q6OOufAKSKd2P1w0yBuyz Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2sCAwLNAzfM7duvHoSaUVh Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2sCAwLNAzfM7duvHoSaUVh Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0OMHIc3h1jXfR6V4GKVVAg Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0OMHIc3h1jXfR6V4GKVVAg Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:3qkQzVZYR8pHsqMwyzam30 Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:3qkQzVZYR8pHsqMwyzam30 Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::updateTrackBlock Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::getTrackBlock Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPlay Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::play index 5 Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::addQueueItems Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::addQueueItems Oct 31 23:22:11 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0bbv6aSL5rcjKCu9Aj2Xxa Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0bbv6aSL5rcjKCu9Aj2Xxa Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1tCAJSYysyhQdSsyIGumaA Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1tCAJSYysyhQdSsyIGumaA Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:40ybb9b105RzAhRZB6iRZv Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:40ybb9b105RzAhRZB6iRZv Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6N8J9G7HWoxRzEWFugXAmm Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6N8J9G7HWoxRzEWFugXAmm Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:7h9IAebaWbzqEIDKWFxvNE Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:7h9IAebaWbzqEIDKWFxvNE Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:7DRk0k2Sd2kZL7pXPgM9FH Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:7DRk0k2Sd2kZL7pXPgM9FH Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0bDbepFJBTWgnbcyiIropA Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0bDbepFJBTWgnbcyiIropA Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6KOhAOGfS5n0HwHHEWKuuU Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6KOhAOGfS5n0HwHHEWKuuU Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:4l7tPloKHNLlVR3lHepp25 Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:4l7tPloKHNLlVR3lHepp25 Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2hQI49sxOIXLZjhabjymgn Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2hQI49sxOIXLZjhabjymgn Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6Lo8tzkqE92ccknEaf2tIZ Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6Lo8tzkqE92ccknEaf2tIZ Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2zKRFXwrLZbEHhgiFBWuQj Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2zKRFXwrLZbEHhgiFBWuQj Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1VEBov3sJwl9d1kXlq0tiu Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1VEBov3sJwl9d1kXlq0tiu Oct 31 23:22:11 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6XjqgFFzrmbr4EFfZ7TWqE Oct 31 23:22:11 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6XjqgFFzrmbr4EFfZ7TWqE Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::stop Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::play index undefined Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::updateTrackBlock Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::getTrackBlock Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:11 volumiobpi volumio[959]: info: CoreStateMachine::startPlaybackTimer Oct 31 23:22:11 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:11 volumiobpi volumio[959]: info: [1761963731994] ControllerSpotify::clearAddPlayTrack Oct 31 23:22:11 volumiobpi volumio[959]: info: Sending Spotify command with payload to local API: /player/play Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=debug msg="resolved context of track" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 23:22:12 volumiobpi volumio[959]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","play_origin":"go-librespot"}} Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=debug msg="selected format OGG_VORBIS_320 (7e9061d017b240f955b9b0a32f10d146fca3d2db)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=debug msg="requested aes key for file 7e9061d017b240f955b9b0a32f10d146fca3d2db, gid: 3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=debug msg="fetched first chunk of 17, total size is 8456808 bytes" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:12 volumiobpi go-librespot[1627]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 23:22:12 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:12-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:3qkQzVZYR8pHsqMwyzam30: ALSA error at snd_pcm_open: No such file or directory" Oct 31 23:22:12 volumiobpi volumio[959]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 23:22:13 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:13-03:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:13 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:13-03:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:13 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:13-03:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:13 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:13-03:00" level=trace msg="sent dealer ping" Oct 31 23:22:13 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:13-03:00" level=trace msg="received dealer pong" Oct 31 23:22:36 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:36-03:00" level=debug msg="handling pause player command from 09c9ef1b0c7bca99e40330e8f1f00561596f08cb" Oct 31 23:22:36 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:36-03:00" level=debug msg="pause track at 0ms" Oct 31 23:22:36 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:36-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:22:36 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:36-03:00" level=debug msg="sending successful reply for dealer request" Oct 31 23:22:36 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:36-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:22:36 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:36-03:00" level=trace msg="emitting websocket event: paused" Oct 31 23:22:36 volumiobpi volumio[959]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","play_origin":"go-librespot"}} Oct 31 23:22:36 volumiobpi volumio[959]: SPOTIFY: PUSH STATE SPOTIFY Oct 31 23:22:36 volumiobpi volumio[959]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 31 23:22:36 volumiobpi volumio[959]: info: CoreCommandRouter::servicePushState Oct 31 23:22:36 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:36 volumiobpi volumio[959]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 31 23:22:36 volumiobpi volumio[959]: verbose: CURRENT POSITION 5 Oct 31 23:22:36 volumiobpi volumio[959]: info: CoreStateMachine::syncState stateService pause Oct 31 23:22:36 volumiobpi volumio[959]: info: CoreStateMachine::syncState currentStatus stop Oct 31 23:22:36 volumiobpi volumio[959]: info: CoreStateMachine::pushState Oct 31 23:22:36 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:36 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 23:22:36 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushState Oct 31 23:22:36 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 11 Oct 31 23:22:37 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:37-03:00" level=debug msg="handling resume player command from 09c9ef1b0c7bca99e40330e8f1f00561596f08cb" Oct 31 23:22:37 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:37-03:00" level=trace msg="seek to 0ms (diff: -17ms, samples: 0, bytes: 3719)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:37 volumiobpi go-librespot[1627]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 23:22:37 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:37-03:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such file or directory" Oct 31 23:22:41 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:41-03:00" level=debug msg="handling skip_next player command from 09c9ef1b0c7bca99e40330e8f1f00561596f08cb" Oct 31 23:22:41 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:41-03:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:41 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:41-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:22:41 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:41-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 23:22:41 volumiobpi volumio[959]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","play_origin":"go-librespot"}} Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="selected format OGG_VORBIS_320 (7e9061d017b240f955b9b0a32f10d146fca3d2db)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="requested aes key for file 7e9061d017b240f955b9b0a32f10d146fca3d2db, gid: 3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="fetched first chunk of 17, total size is 8456808 bytes" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=info msg="loaded track \"I Want To Break Free - Live At Rock In Rio, Lisbon, Portugal, 2016\" (paused: true, position: 0ms, duration: 213636ms, prefetched: false)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=trace msg="emitting websocket event: metadata" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=trace msg="emitting websocket event: stopped" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="sending successful reply for dealer request" Oct 31 23:22:42 volumiobpi volumio[959]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","name":"I Want To Break Free - Live At Rock In Rio, Lisbon, Portugal, 2016","artist_names":["Queen","Adam Lambert"],"album_name":"Live Around The World (Deluxe)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0272a659e4c3bda377f2e9b162","position":0,"duration":213636,"release_date":"year:2020 month:10 day:2","track_number":6,"disc_number":1}} Oct 31 23:22:42 volumiobpi volumio[959]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}} Oct 31 23:22:42 volumiobpi volumio[959]: SPOTIFY: PUSH STATE SPOTIFY Oct 31 23:22:42 volumiobpi volumio[959]: SPOTIFY: {"status":"stop","service":"spop","title":"I Want To Break Free - Live At Rock In Rio, Lisbon, Portugal, 2016","artist":"Queen, Adam Lambert","album":"Live Around The World (Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e0272a659e4c3bda377f2e9b162","uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreCommandRouter::servicePushState Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreStateMachine::pushState Oct 31 23:22:42 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushState Oct 31 23:22:42 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:42 volumiobpi volumio[959]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"I Want To Break Free - Live At Rock In Rio, Lisbon, Portugal, 2016","artist":"Queen, Adam Lambert","album":"Live Around The World (Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e0272a659e4c3bda377f2e9b162","uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 31 23:22:42 volumiobpi volumio[959]: verbose: CURRENT POSITION 5 Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreStateMachine::syncState stateService stop Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreStateMachine::syncState currentStatus stop Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreStateMachine::pushState Oct 31 23:22:42 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushState Oct 31 23:22:42 volumiobpi volumio[959]: info: No code Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreStateMachine::pushState Oct 31 23:22:42 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushState Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=trace msg="emitting websocket event: paused" Oct 31 23:22:42 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:42-03:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:42 volumiobpi volumio[959]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","play_origin":"go-librespot"}} Oct 31 23:22:42 volumiobpi volumio[959]: SPOTIFY: PUSH STATE SPOTIFY Oct 31 23:22:42 volumiobpi volumio[959]: SPOTIFY: {"status":"pause","service":"spop","title":"I Want To Break Free - Live At Rock In Rio, Lisbon, Portugal, 2016","artist":"Queen, Adam Lambert","album":"Live Around The World (Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e0272a659e4c3bda377f2e9b162","uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 31 23:22:42 volumiobpi volumio[959]: info: CoreCommandRouter::servicePushState Oct 31 23:22:43 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:43 volumiobpi volumio[959]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"I Want To Break Free - Live At Rock In Rio, Lisbon, Portugal, 2016","artist":"Queen, Adam Lambert","album":"Live Around The World (Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e0272a659e4c3bda377f2e9b162","uri":"spotify:track:3qkQzVZYR8pHsqMwyzam30","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 31 23:22:43 volumiobpi volumio[959]: verbose: CURRENT POSITION 5 Oct 31 23:22:43 volumiobpi volumio[959]: info: CoreStateMachine::syncState stateService pause Oct 31 23:22:43 volumiobpi volumio[959]: info: CoreStateMachine::syncState currentStatus stop Oct 31 23:22:43 volumiobpi volumio[959]: info: CoreStateMachine::pushState Oct 31 23:22:43 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:22:43 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 23:22:43 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushState Oct 31 23:22:43 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 11 Oct 31 23:22:43 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 11 Oct 31 23:22:43 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 11 Oct 31 23:22:43 volumiobpi volumio[959]: SPOTIFY: RECEIVED VOLUMIO VOLUME 11 Oct 31 23:22:43 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:43-03:00" level=trace msg="sent dealer ping" Oct 31 23:22:43 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:43-03:00" level=trace msg="received dealer pong" Oct 31 23:22:47 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:47-03:00" level=debug msg="handling resume player command from 09c9ef1b0c7bca99e40330e8f1f00561596f08cb" Oct 31 23:22:47 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:47-03:00" level=trace msg="seek to 0ms (diff: -17ms, samples: 0, bytes: 3719)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:47 volumiobpi go-librespot[1627]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 23:22:47 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:47-03:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such file or directory" Oct 31 23:22:59 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:59-03:00" level=debug msg="handling resume player command from 09c9ef1b0c7bca99e40330e8f1f00561596f08cb" Oct 31 23:22:59 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:59-03:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:59 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:59-03:00" level=trace msg="seek to 0ms (diff: -17ms, samples: 0, bytes: 3719)" uri="spotify:track:3qkQzVZYR8pHsqMwyzam30" Oct 31 23:22:59 volumiobpi go-librespot[1627]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 23:22:59 volumiobpi go-librespot[1627]: time="2025-10-31T23:22:59-03:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such file or directory" Oct 31 23:23:05 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 23:23:05 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 23:23:05 volumiobpi volumio[959]: info: Discovery: Getting this device information Oct 31 23:23:05 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:05 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:05 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 23:23:05 volumiobpi volumio[959]: verbose: New Socket.io Connection to 192.168.0.57:3000 from 192.168.0.79 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Oct 31 23:23:05 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:05 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:05 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 31 23:23:05 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 31 23:23:08 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:08 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:08 volumiobpi volumio[959]: verbose: New Socket.io Connection to 192.168.0.57:3000 from 192.168.0.79 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Oct 31 23:23:08 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:08 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:08 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 31 23:23:08 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 31 23:23:08 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:08 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:09 volumiobpi sudo[3933]: volumio : unable to resolve host volumiobpi Oct 31 23:23:09 volumiobpi sudo[3933]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 23:23:09 volumiobpi sudo[3933]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 31 23:23:09 volumiobpi sudo[3933]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 23:23:09 volumiobpi sudo[3933]: pam_unix(sudo:session): session closed for user root Oct 31 23:23:09 volumiobpi sudo[3935]: volumio : unable to resolve host volumiobpi Oct 31 23:23:09 volumiobpi sudo[3935]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 23:23:09 volumiobpi sudo[3935]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 31 23:23:09 volumiobpi sudo[3935]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 23:23:09 volumiobpi sudo[3935]: pam_unix(sudo:session): session closed for user root Oct 31 23:23:09 volumiobpi volumio[959]: verbose: New Socket.io Connection to 192.168.0.57 from 192.168.0.79 UA: Mozilla/5.0 (Linux; Android 15; 23129RA5FL Build/AQ3A.240829.003; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Oct 31 23:23:10 volumiobpi sudo[3941]: volumio : unable to resolve host volumiobpi Oct 31 23:23:10 volumiobpi sudo[3941]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 23:23:10 volumiobpi sudo[3941]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 31 23:23:10 volumiobpi sudo[3941]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 23:23:10 volumiobpi sudo[3943]: volumio : unable to resolve host volumiobpi Oct 31 23:23:10 volumiobpi sudo[3943]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 23:23:10 volumiobpi sudo[3941]: pam_unix(sudo:session): session closed for user root Oct 31 23:23:10 volumiobpi sudo[3943]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 31 23:23:10 volumiobpi sudo[3943]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 23:23:11 volumiobpi sudo[3943]: pam_unix(sudo:session): session closed for user root Oct 31 23:23:11 volumiobpi volumio[959]: verbose: New Socket.io Connection to 192.168.0.57 from 192.168.0.79 UA: Mozilla/5.0 (Linux; Android 15; 23129RA5FL Build/AQ3A.240829.003; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Oct 31 23:23:11 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 31 23:23:11 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetVisibleSources Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:12 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetQueue Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreStateMachine::getQueue Oct 31 23:23:12 volumiobpi volumio[959]: info: CorePlayQueue::getQueue Oct 31 23:23:12 volumiobpi volumio[959]: info: Listing playlists Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 31 23:23:12 volumiobpi volumio[959]: info: Received Get System Info Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 23:23:12 volumiobpi volumio[959]: info: Discovery: Getting this device information Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:12 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:12 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 31 23:23:12 volumiobpi volumio[959]: info: Received Get System Info Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 23:23:12 volumiobpi volumio[959]: info: Discovery: Getting this device information Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:12 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 5 Oct 31 23:23:12 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 23:23:13 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:13-03:00" level=trace msg="sent dealer ping" Oct 31 23:23:13 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:13-03:00" level=trace msg="received dealer pong" Oct 31 23:23:13 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::ClearQueue Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::stop Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::clearPlayQueue Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::addQueueItems Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::addQueueItems Oct 31 23:23:13 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2lD6W5w72NsrjnKT5HBoCM Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2lD6W5w72NsrjnKT5HBoCM Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1cQygsHlGII3a0H6DmUpA2 Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1cQygsHlGII3a0H6DmUpA2 Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:3Q6OOufAKSKd2P1w0yBuyz Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:3Q6OOufAKSKd2P1w0yBuyz Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2sCAwLNAzfM7duvHoSaUVh Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2sCAwLNAzfM7duvHoSaUVh Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0OMHIc3h1jXfR6V4GKVVAg Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0OMHIc3h1jXfR6V4GKVVAg Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:3qkQzVZYR8pHsqMwyzam30 Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:3qkQzVZYR8pHsqMwyzam30 Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0bbv6aSL5rcjKCu9Aj2Xxa Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0bbv6aSL5rcjKCu9Aj2Xxa Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1tCAJSYysyhQdSsyIGumaA Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1tCAJSYysyhQdSsyIGumaA Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::updateTrackBlock Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::getTrackBlock Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPlay Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::play index 7 Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::addQueueItems Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::addQueueItems Oct 31 23:23:13 volumiobpi volumio[959]: info: Preload queue cleared Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:40ybb9b105RzAhRZB6iRZv Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:40ybb9b105RzAhRZB6iRZv Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6N8J9G7HWoxRzEWFugXAmm Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6N8J9G7HWoxRzEWFugXAmm Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:7h9IAebaWbzqEIDKWFxvNE Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:7h9IAebaWbzqEIDKWFxvNE Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:7DRk0k2Sd2kZL7pXPgM9FH Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:7DRk0k2Sd2kZL7pXPgM9FH Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:0bDbepFJBTWgnbcyiIropA Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:0bDbepFJBTWgnbcyiIropA Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6KOhAOGfS5n0HwHHEWKuuU Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6KOhAOGfS5n0HwHHEWKuuU Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:4l7tPloKHNLlVR3lHepp25 Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:4l7tPloKHNLlVR3lHepp25 Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2hQI49sxOIXLZjhabjymgn Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2hQI49sxOIXLZjhabjymgn Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6Lo8tzkqE92ccknEaf2tIZ Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6Lo8tzkqE92ccknEaf2tIZ Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:2zKRFXwrLZbEHhgiFBWuQj Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:2zKRFXwrLZbEHhgiFBWuQj Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:1VEBov3sJwl9d1kXlq0tiu Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:1VEBov3sJwl9d1kXlq0tiu Oct 31 23:23:13 volumiobpi volumio[959]: info: Adding Item to queue: spotify:track:6XjqgFFzrmbr4EFfZ7TWqE Oct 31 23:23:13 volumiobpi volumio[959]: info: Using cached record of: spotify:track:6XjqgFFzrmbr4EFfZ7TWqE Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::stop Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPushQueue Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::saveQueue Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::play index undefined Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::updateTrackBlock Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::getTrackBlock Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 7 Oct 31 23:23:13 volumiobpi volumio[959]: info: CoreStateMachine::startPlaybackTimer Oct 31 23:23:13 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 7 Oct 31 23:23:13 volumiobpi volumio[959]: info: [1761963793978] ControllerSpotify::clearAddPlayTrack Oct 31 23:23:13 volumiobpi volumio[959]: info: Sending Spotify command with payload to local API: /player/play Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 31 23:23:14 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:14-03:00" level=debug msg="resolved context of track" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:14 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:14-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:14 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:14-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 31 23:23:14 volumiobpi volumio[959]: info: Received Get System Info Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 23:23:14 volumiobpi volumio[959]: info: Discovery: Getting this device information Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:14 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 7 Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 23:23:14 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:14-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:23:14 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:14-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 23:23:14 volumiobpi volumio[959]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1tCAJSYysyhQdSsyIGumaA","play_origin":"go-librespot"}} Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreCommandRouter::volumioPlay Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreStateMachine::play index undefined Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 23:23:14 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 7 Oct 31 23:23:14 volumiobpi volumio[959]: info: CoreStateMachine::startPlaybackTimer Oct 31 23:23:14 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 7 Oct 31 23:23:14 volumiobpi volumio[959]: info: [1761963794930] ControllerSpotify::clearAddPlayTrack Oct 31 23:23:14 volumiobpi volumio[959]: info: Sending Spotify command with payload to local API: /player/play Oct 31 23:23:14 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:14-03:00" level=debug msg="selected format OGG_VORBIS_320 (d99f21a5a6f656ed2cd78e0b1b0215ea5357ac5a)" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:14 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:14-03:00" level=debug msg="requested aes key for file d99f21a5a6f656ed2cd78e0b1b0215ea5357ac5a, gid: 1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=debug msg="fetched first chunk of 19, total size is 9652928 bytes" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:1tCAJSYysyhQdSsyIGumaA: ALSA error at snd_pcm_open: No such file or directory" Oct 31 23:23:15 volumiobpi volumio[959]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=debug msg="resolved context of track" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 23:23:15 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:15-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 23:23:15 volumiobpi volumio[959]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1tCAJSYysyhQdSsyIGumaA","play_origin":"go-librespot"}} Oct 31 23:23:16 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:16-03:00" level=debug msg="selected format OGG_VORBIS_320 (d99f21a5a6f656ed2cd78e0b1b0215ea5357ac5a)" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:16 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:16-03:00" level=debug msg="requested aes key for file d99f21a5a6f656ed2cd78e0b1b0215ea5357ac5a, gid: 1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:16 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:16-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:16 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:16-03:00" level=debug msg="fetched first chunk of 19, total size is 9652928 bytes" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:16 volumiobpi go-librespot[1627]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 23:23:16 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:16-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:1tCAJSYysyhQdSsyIGumaA: ALSA error at snd_pcm_open: No such file or directory" Oct 31 23:23:16 volumiobpi volumio[959]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 23:23:16 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:16-03:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:16 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:16-03:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:16 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:16-03:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:1tCAJSYysyhQdSsyIGumaA" Oct 31 23:23:21 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 31 23:23:23 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 31 23:23:23 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 31 23:23:29 volumiobpi volumio[959]: info: Received Get System Info Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 23:23:29 volumiobpi volumio[959]: info: Discovery: Getting this device information Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:29 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 7 Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 31 23:23:29 volumiobpi volumio[959]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 31 23:23:29 volumiobpi volumio[959]: info: Received Get System Version Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 23:23:29 volumiobpi volumio[959]: info: Received Get System Info Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 23:23:29 volumiobpi volumio[959]: info: Discovery: Getting this device information Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:29 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 7 Oct 31 23:23:29 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 23:23:31 volumiobpi volumio[959]: info: Starting Uninstall of plugin music_service - spop Oct 31 23:23:31 volumiobpi volumio[959]: info: Uninstalling plugin spop Oct 31 23:23:31 volumiobpi go-librespot[1627]: time="2025-10-31T23:23:31-03:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Oct 31 23:23:31 volumiobpi volumio[959]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Oct 31 23:23:31 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 23:23:31 volumiobpi sudo[4024]: volumio : unable to resolve host volumiobpi Oct 31 23:23:31 volumiobpi sudo[4024]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 23:23:31 volumiobpi volumio[959]: info: Disabling plugin spop Oct 31 23:23:31 volumiobpi sudo[4024]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Oct 31 23:23:31 volumiobpi sudo[4024]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 23:23:32 volumiobpi systemd[1]: Stopping go-librespot Daemon... Oct 31 23:23:32 volumiobpi systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 31 23:23:32 volumiobpi volumio[959]: info: Checking if uninstall.sh is present Oct 31 23:23:32 volumiobpi volumio[959]: info: Connection to go-librespot Websocket closed Oct 31 23:23:32 volumiobpi systemd[1]: go-librespot-daemon.service: Succeeded. Oct 31 23:23:32 volumiobpi systemd[1]: Stopped go-librespot Daemon. Oct 31 23:23:32 volumiobpi sudo[4024]: pam_unix(sudo:session): session closed for user root Oct 31 23:23:32 volumiobpi volumio[959]: info: Executing uninstall.sh Oct 31 23:23:32 volumiobpi sudo[4028]: volumio : unable to resolve host volumiobpi Oct 31 23:23:32 volumiobpi sudo[4028]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 23:23:32 volumiobpi sudo[4028]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/music_service/spop/uninstall.sh Oct 31 23:23:32 volumiobpi sudo[4028]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 23:23:32 volumiobpi sudo[4028]: pam_unix(sudo:session): session closed for user root Oct 31 23:23:32 volumiobpi volumio[959]: info: Uninstall script completed Oct 31 23:23:32 volumiobpi volumio[959]: info: Removing plugin spop from configuration Oct 31 23:23:32 volumiobpi volumio[959]: info: Successfully removed spop configuration files Oct 31 23:23:32 volumiobpi volumio[959]: info: Plugin folders cleanup Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning into folder /volumio/app/plugins/ Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning category audio_interface Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning category miscellanea Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning category music_service Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning category plugins.json Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning category system_controller Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning category user_interface Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning into folder /data/plugins/ Oct 31 23:23:32 volumiobpi volumio[959]: info: Scanning category music_service Oct 31 23:23:32 volumiobpi volumio[959]: info: Cleaning folder for spop Oct 31 23:23:36 volumiobpi volumio[959]: info: Scanning category system_controller Oct 31 23:23:36 volumiobpi volumio[959]: info: Plugin folders cleanup completed Oct 31 23:23:36 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 31 23:23:36 volumiobpi volumio[959]: info: [{"prettyName":"Amplifier Switch","name":"ampswitch","category":"system_controller","version":"0.2.1","icon":"fa-power-off","isManuallyInstalled":false,"enabled":true,"active":false}] Oct 31 23:23:36 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 31 23:23:36 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 23:23:36 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 23:23:36 volumiobpi volumio[959]: info: Discovery: Getting this device information Oct 31 23:23:36 volumiobpi volumio[959]: info: CoreCommandRouter::volumioGetState Oct 31 23:23:36 volumiobpi volumio[959]: info: CorePlayQueue::getTrack 7 Oct 31 23:23:36 volumiobpi volumio[959]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 23:23:48 volumiobpi volumio[959]: info: Starting Uninstall of plugin system_controller - ampswitch Oct 31 23:23:48 volumiobpi volumio[959]: info: Uninstalling plugin ampswitch Oct 31 23:23:48 volumiobpi volumio[959]: info: [ASDebug] Port: 24 Oct 31 23:23:48 volumiobpi volumio[959]: info: [ASDebug] Inverted: false Oct 31 23:23:48 volumiobpi volumio[959]: info: [ASDebug] Delay: 720 Oct 31 23:23:48 volumiobpi volumio[959]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 23:23:48 volumiobpi volumio[959]: TypeError: Cannot read property 'unexport' of undefined Oct 31 23:23:48 volumiobpi volumio[959]: at AmpSwitchController.freeGPIO (/data/plugins/system_controller/ampswitch/index.js:242:19) Oct 31 23:23:48 volumiobpi volumio[959]: at AmpSwitchController.onStop (/data/plugins/system_controller/ampswitch/index.js:90:10) Oct 31 23:23:48 volumiobpi volumio[959]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Oct 31 23:23:48 volumiobpi volumio[959]: at PluginManager.unInstallPlugin (/volumio/app/pluginmanager.js:1449:10) Oct 31 23:23:48 volumiobpi volumio[959]: at CoreCommandRouter.unInstallPlugin (/volumio/app/index.js:1484:22) Oct 31 23:23:48 volumiobpi volumio[959]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1260:45) Oct 31 23:23:48 volumiobpi volumio[959]: at Socket.emit (events.js:400:28) Oct 31 23:23:48 volumiobpi volumio[959]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 31 23:23:48 volumiobpi volumio[959]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Oct 31 23:23:48 volumiobpi volumio[959]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 23:23:50 volumiobpi sudo[4082]: volumio : unable to resolve host volumiobpi Oct 31 23:23:50 volumiobpi sudo[4082]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 23:23:50 volumiobpi sudo[4082]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-31 23:22 Oct 31 23:23:50 volumiobpi sudo[4082]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="669bb6cc406bb77b11c5184fedb8a4dfd19ba4ec" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 29 Jul 2025 12:10:02 PM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="bananapim1" VOLUMIO_DEVICENAME="BananaPi M1" VOLUMIO_HASH="a856c34c22162ee39711d68f761997f2"