-- Logs begin at Fri 2025-10-31 22:25:45 -03, end at Fri 2025-10-31 22:40:01 -03. -- Oct 31 22:39:00 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:00-03:00" level=error msg="did not receive last pong from dealer, 240s passed" Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 31 22:39:01 volumiobpi volumio[963]: info: Received Get System Info Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 22:39:01 volumiobpi volumio[963]: info: Discovery: Getting this device information Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetState Oct 31 22:39:01 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 6 Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPlay Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreStateMachine::play index undefined Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 31 22:39:01 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 6 Oct 31 22:39:01 volumiobpi volumio[963]: info: CoreStateMachine::startPlaybackTimer Oct 31 22:39:01 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 6 Oct 31 22:39:01 volumiobpi volumio[963]: info: [1761961141796] ControllerSpotify::clearAddPlayTrack Oct 31 22:39:01 volumiobpi volumio[963]: info: Sending Spotify command with payload to local API: /player/play Oct 31 22:39:02 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 31 22:39:02 volumiobpi volumio[963]: info: Received Get System Info Oct 31 22:39:02 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 22:39:02 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 22:39:02 volumiobpi volumio[963]: info: Discovery: Getting this device information Oct 31 22:39:02 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetState Oct 31 22:39:02 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 6 Oct 31 22:39:02 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 22:39:03 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPrevious Oct 31 22:39:03 volumiobpi volumio[963]: info: CoreStateMachine::previous Oct 31 22:39:03 volumiobpi volumio[963]: info: CoreStateMachine::updateTrackBlock Oct 31 22:39:03 volumiobpi volumio[963]: info: CorePlayQueue::getTrackBlock Oct 31 22:39:03 volumiobpi volumio[963]: info: CoreStateMachine::pushState Oct 31 22:39:03 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 5 Oct 31 22:39:03 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 22:39:03 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPushState Oct 31 22:39:03 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:03-03:00" level=debug msg="resolved context of track" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:03 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:03-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:03 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:03-03:00" level=debug msg="loading track (paused: false, position: 5ms)" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:03 volumiobpi volumio[963]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Oct 31 22:39:03 volumiobpi volumio[963]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Oct 31 22:39:03 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:03-03:00" level=debug msg="dealer connection opened" Oct 31 22:39:03 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:03-03:00" level=debug msg="re-established dealer connection" Oct 31 22:39:03 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:03-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 22:39:03 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:03-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 22:39:03 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4rDbp1vnvEhieiccprPMdI","play_origin":"go-librespot"}} Oct 31 22:39:03 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4rDbp1vnvEhieiccprPMdI","play_origin":"go-librespot"}} Oct 31 22:39:04 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPrevious Oct 31 22:39:04 volumiobpi volumio[963]: info: CoreStateMachine::previous Oct 31 22:39:04 volumiobpi volumio[963]: info: CoreStateMachine::updateTrackBlock Oct 31 22:39:04 volumiobpi volumio[963]: info: CorePlayQueue::getTrackBlock Oct 31 22:39:04 volumiobpi volumio[963]: info: CoreStateMachine::pushState Oct 31 22:39:04 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 4 Oct 31 22:39:04 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 22:39:04 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPushState Oct 31 22:39:04 volumiobpi volumio[963]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Oct 31 22:39:04 volumiobpi volumio[963]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Oct 31 22:39:07 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:07-03:00" level=debug msg="selected format OGG_VORBIS_320 (cd9c6d61a49ff5c28c40da7478ecbb5486d0639d)" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:07 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:07-03:00" level=debug msg="requested aes key for file cd9c6d61a49ff5c28c40da7478ecbb5486d0639d, gid: 4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:07 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPlay Oct 31 22:39:07 volumiobpi volumio[963]: info: CoreStateMachine::play index undefined Oct 31 22:39:07 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:07 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 4 Oct 31 22:39:07 volumiobpi volumio[963]: info: CoreStateMachine::startPlaybackTimer Oct 31 22:39:07 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 4 Oct 31 22:39:07 volumiobpi volumio[963]: info: [1761961147341] ControllerSpotify::clearAddPlayTrack Oct 31 22:39:07 volumiobpi volumio[963]: info: Sending Spotify command with payload to local API: /player/play Oct 31 22:39:07 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:07-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="fetched first chunk of 23, total size is 11575292 bytes" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=trace msg="seek to 5ms (diff: 5ms, samples: 220, bytes: 0)" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:08 volumiobpi go-librespot[2788]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-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:4rDbp1vnvEhieiccprPMdI: ALSA error at snd_pcm_open: No such file or directory" Oct 31 22:39:08 volumiobpi volumio[963]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="resolved context of track" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="loading track (paused: false, position: 8ms)" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 22:39:08 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4pbJqGIASGPr0ZpGpnWkDn","play_origin":"go-librespot"}} Oct 31 22:39:08 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4pbJqGIASGPr0ZpGpnWkDn","play_origin":"go-librespot"}} Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="selected format OGG_VORBIS_320 (e3463b46d548d2612150f10f49840389849007b1)" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:08 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:08-03:00" level=debug msg="requested aes key for file e3463b46d548d2612150f10f49840389849007b1, gid: 4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:09 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-03:00" level=debug msg="fetched first chunk of 11, total size is 5703472 bytes" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-03:00" level=trace msg="seek to 8ms (diff: 8ms, samples: 352, bytes: 0)" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:09 volumiobpi go-librespot[2788]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-03:00" level=debug msg="received connection id: NDAxNGNkY2EtMGQ3...RjY3MDI1Qzc2Qg==" Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-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:4pbJqGIASGPr0ZpGpnWkDn: ALSA error at snd_pcm_open: No such file or directory" Oct 31 22:39:09 volumiobpi volumio[963]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-03:00" level=debug msg="put connect state because NEW_DEVICE" Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-03:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-03:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:09 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:09-03:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:4pbJqGIASGPr0ZpGpnWkDn" Oct 31 22:39:12 volumiobpi volumio[963]: info: CoreCommandRouter::volumioNext Oct 31 22:39:12 volumiobpi volumio[963]: info: CoreStateMachine::next Oct 31 22:39:12 volumiobpi volumio[963]: info: CoreStateMachine::stop Oct 31 22:39:12 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:12 volumiobpi volumio[963]: info: CoreStateMachine::play index undefined Oct 31 22:39:12 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:12 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 5 Oct 31 22:39:12 volumiobpi volumio[963]: info: CoreStateMachine::startPlaybackTimer Oct 31 22:39:12 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 5 Oct 31 22:39:12 volumiobpi volumio[963]: info: [1761961152911] ControllerSpotify::clearAddPlayTrack Oct 31 22:39:12 volumiobpi volumio[963]: info: Sending Spotify command with payload to local API: /player/play Oct 31 22:39:12 volumiobpi volumio[963]: info: CoreStateMachine::updateTrackBlock Oct 31 22:39:12 volumiobpi volumio[963]: info: CorePlayQueue::getTrackBlock Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=debug msg="resolved context of track" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 22:39:13 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6xdLJrVj4vIXwhuG8TMopk","play_origin":"go-librespot"}} Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=debug msg="selected format OGG_VORBIS_320 (8f9865c688897f2a89e2010e001512704c66f5b6)" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=debug msg="requested aes key for file 8f9865c688897f2a89e2010e001512704c66f5b6, gid: 6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=debug msg="fetched first chunk of 15, total size is 7341072 bytes" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:13 volumiobpi go-librespot[2788]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 22:39:13 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:13-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:6xdLJrVj4vIXwhuG8TMopk: ALSA error at snd_pcm_open: No such file or directory" Oct 31 22:39:13 volumiobpi volumio[963]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 22:39:14 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:14-03:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:14 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:14-03:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:14 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:14-03:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:6xdLJrVj4vIXwhuG8TMopk" Oct 31 22:39:15 volumiobpi volumio[963]: info: CoreCommandRouter::volumioNext Oct 31 22:39:15 volumiobpi volumio[963]: info: CoreStateMachine::next Oct 31 22:39:15 volumiobpi volumio[963]: info: CoreStateMachine::stop Oct 31 22:39:15 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:15 volumiobpi volumio[963]: info: CoreStateMachine::play index undefined Oct 31 22:39:15 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:15 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 6 Oct 31 22:39:15 volumiobpi volumio[963]: info: CoreStateMachine::startPlaybackTimer Oct 31 22:39:15 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 6 Oct 31 22:39:15 volumiobpi volumio[963]: info: [1761961155363] ControllerSpotify::clearAddPlayTrack Oct 31 22:39:15 volumiobpi volumio[963]: info: Sending Spotify command with payload to local API: /player/play Oct 31 22:39:15 volumiobpi volumio[963]: info: CoreStateMachine::updateTrackBlock Oct 31 22:39:15 volumiobpi volumio[963]: info: CorePlayQueue::getTrackBlock Oct 31 22:39:15 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:15-03:00" level=debug msg="resolved context of track" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:15 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:15-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:15 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:15-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:15 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:15-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 22:39:15 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:15-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 22:39:15 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4rDbp1vnvEhieiccprPMdI","play_origin":"go-librespot"}} Oct 31 22:39:15 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4rDbp1vnvEhieiccprPMdI","play_origin":"go-librespot"}} Oct 31 22:39:15 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:15-03:00" level=debug msg="selected format OGG_VORBIS_320 (cd9c6d61a49ff5c28c40da7478ecbb5486d0639d)" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:15 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:15-03:00" level=debug msg="requested aes key for file cd9c6d61a49ff5c28c40da7478ecbb5486d0639d, gid: 4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:16 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:16-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:16 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:16-03:00" level=debug msg="fetched first chunk of 23, total size is 11575292 bytes" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:16 volumiobpi go-librespot[2788]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 22:39:16 volumiobpi go-librespot[2788]: time="2025-10-31T22:39: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:4rDbp1vnvEhieiccprPMdI: ALSA error at snd_pcm_open: No such file or directory" Oct 31 22:39:16 volumiobpi volumio[963]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 22:39:16 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:16-03:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:16 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:16-03:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:16 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:16-03:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:4rDbp1vnvEhieiccprPMdI" Oct 31 22:39:18 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 31 22:39:18 volumiobpi volumio[963]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 31 22:39:18 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 31 22:39:18 volumiobpi volumio[963]: info: Received Get System Version Oct 31 22:39:18 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 22:39:18 volumiobpi volumio[963]: info: Received Get System Info Oct 31 22:39:18 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 22:39:18 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 22:39:18 volumiobpi volumio[963]: info: Discovery: Getting this device information Oct 31 22:39:18 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetState Oct 31 22:39:18 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 6 Oct 31 22:39:18 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 22:39:22 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetQueue Oct 31 22:39:22 volumiobpi volumio[963]: info: CoreStateMachine::getQueue Oct 31 22:39:22 volumiobpi volumio[963]: info: CorePlayQueue::getQueue Oct 31 22:39:24 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 22:39:24 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 22:39:24 volumiobpi volumio[963]: info: Discovery: Getting this device information Oct 31 22:39:24 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetState Oct 31 22:39:24 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 6 Oct 31 22:39:24 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 22:39:28 volumiobpi volumio[963]: info: Preload queue cleared Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::ClearQueue Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::stop Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::clearPlayQueue Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::saveQueue Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPushQueue Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::addQueueItems Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::addQueueItems Oct 31 22:39:28 volumiobpi volumio[963]: info: Preload queue cleared Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:4u7EnebtmKWzUH433cf5Qv Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:4u7EnebtmKWzUH433cf5Qv Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:5T8EDUDqKcs6OSOwEsfqG7 Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:5T8EDUDqKcs6OSOwEsfqG7 Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:2fuCquhmrzHpu5xcA1ci9x Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:2fuCquhmrzHpu5xcA1ci9x Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:5vdp5UmvTsnMEMESIF2Ym7 Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:5vdp5UmvTsnMEMESIF2Ym7 Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:4pbJqGIASGPr0ZpGpnWkDn Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:4pbJqGIASGPr0ZpGpnWkDn Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:6xdLJrVj4vIXwhuG8TMopk Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:6xdLJrVj4vIXwhuG8TMopk Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:4rDbp1vnvEhieiccprPMdI Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:4rDbp1vnvEhieiccprPMdI Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:4cIPLtg1avt2Jm3ne9S1zy Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:4cIPLtg1avt2Jm3ne9S1zy Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPushQueue Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::saveQueue Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::updateTrackBlock Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::getTrackBlock Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPlay Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::play index 7 Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::addQueueItems Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::addQueueItems Oct 31 22:39:28 volumiobpi volumio[963]: info: Preload queue cleared Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:1nQRg9q9uwALGzouOX5OyQ Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:1nQRg9q9uwALGzouOX5OyQ Oct 31 22:39:28 volumiobpi volumio[963]: info: Adding Item to queue: spotify:track:1lCRw5FEZ1gPDNPzy1K4zW Oct 31 22:39:28 volumiobpi volumio[963]: info: Using cached record of: spotify:track:1lCRw5FEZ1gPDNPzy1K4zW Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::stop Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreCommandRouter::volumioPushQueue Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::saveQueue Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::play index undefined Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::updateTrackBlock Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::getTrackBlock Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 7 Oct 31 22:39:28 volumiobpi volumio[963]: info: CoreStateMachine::startPlaybackTimer Oct 31 22:39:28 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 7 Oct 31 22:39:28 volumiobpi volumio[963]: info: [1761961168758] ControllerSpotify::clearAddPlayTrack Oct 31 22:39:28 volumiobpi volumio[963]: info: Sending Spotify command with payload to local API: /player/play Oct 31 22:39:28 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:28-03:00" level=debug msg="resolved context of track" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:28 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:28-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:28 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:28-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 22:39:29 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4cIPLtg1avt2Jm3ne9S1zy","play_origin":"go-librespot"}} Oct 31 22:39:29 volumiobpi volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4cIPLtg1avt2Jm3ne9S1zy","play_origin":"go-librespot"}} Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=debug msg="selected format OGG_VORBIS_320 (ae9a3dd1a3cd5a7a4797e81dd8cf3db019a2ffa5)" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=debug msg="requested aes key for file ae9a3dd1a3cd5a7a4797e81dd8cf3db019a2ffa5, gid: 4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=debug msg="fetched first chunk of 14, total size is 6947468 bytes" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:29 volumiobpi go-librespot[2788]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-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:4cIPLtg1avt2Jm3ne9S1zy: ALSA error at snd_pcm_open: No such file or directory" Oct 31 22:39:29 volumiobpi volumio[963]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:29 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:29-03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Oct 31 22:39:30 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:30-03:00" level=trace msg="sent dealer ping" Oct 31 22:39:30 volumiobpi go-librespot[2788]: time="2025-10-31T22:39:30-03:00" level=trace msg="received dealer pong" Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 31 22:39:37 volumiobpi volumio[963]: info: Retrieving Cloud Streaming UI Oct 31 22:39:37 volumiobpi volumio[963]: info: Getting Tidal Cloud Configuration Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 31 22:39:37 volumiobpi volumio[963]: info: Getting Qobuz Cloud Configuration Oct 31 22:39:37 volumiobpi volumio[963]: info: Asking plugin for UI Config Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 31 22:39:37 volumiobpi volumio[963]: info: Getting Spotify Cloud Configuration Oct 31 22:39:37 volumiobpi volumio[963]: info: Asking plugin for UI Config Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 31 22:39:37 volumiobpi volumio[963]: info: Saving Spotify Acccount Oct 31 22:39:37 volumiobpi volumio[963]: info: Got Tidal Cloud Configuration Oct 31 22:39:37 volumiobpi volumio[963]: info: Got it Oct 31 22:39:37 volumiobpi volumio[963]: info: Got it Oct 31 22:39:37 volumiobpi volumio[963]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 31 22:39:37 volumiobpi volumio[963]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetBrowseSources Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetBrowseSources Oct 31 22:39:37 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetBrowseSources Oct 31 22:39:38 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 31 22:39:38 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 31 22:39:42 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 31 22:39:46 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 31 22:39:46 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 31 22:39:54 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 31 22:39:54 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 31 22:39:54 volumiobpi volumio[963]: info: Discovery: Getting this device information Oct 31 22:39:54 volumiobpi volumio[963]: info: CoreCommandRouter::volumioGetState Oct 31 22:39:54 volumiobpi volumio[963]: info: CorePlayQueue::getTrack 7 Oct 31 22:39:54 volumiobpi volumio[963]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 22:39:58 volumiobpi volumio[963]: info: Starting Uninstall of plugin system_controller - ampswitch Oct 31 22:39:58 volumiobpi volumio[963]: info: Uninstalling plugin ampswitch Oct 31 22:39:58 volumiobpi volumio[963]: info: [ASDebug] Port: 24 Oct 31 22:39:58 volumiobpi volumio[963]: info: [ASDebug] Inverted: false Oct 31 22:39:58 volumiobpi volumio[963]: info: [ASDebug] Delay: 720 Oct 31 22:39:58 volumiobpi volumio[963]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 22:39:58 volumiobpi volumio[963]: TypeError: Cannot read property 'unexport' of undefined Oct 31 22:39:58 volumiobpi volumio[963]: at AmpSwitchController.freeGPIO (/data/plugins/system_controller/ampswitch/index.js:242:19) Oct 31 22:39:58 volumiobpi volumio[963]: at AmpSwitchController.onStop (/data/plugins/system_controller/ampswitch/index.js:90:10) Oct 31 22:39:58 volumiobpi volumio[963]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Oct 31 22:39:58 volumiobpi volumio[963]: at PluginManager.unInstallPlugin (/volumio/app/pluginmanager.js:1449:10) Oct 31 22:39:58 volumiobpi volumio[963]: at CoreCommandRouter.unInstallPlugin (/volumio/app/index.js:1484:22) Oct 31 22:39:58 volumiobpi volumio[963]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1260:45) Oct 31 22:39:58 volumiobpi volumio[963]: at Socket.emit (events.js:400:28) Oct 31 22:39:58 volumiobpi volumio[963]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 31 22:39:58 volumiobpi volumio[963]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Oct 31 22:39:58 volumiobpi volumio[963]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 22:40:00 volumiobpi go-librespot[2788]: time="2025-10-31T22:40:00-03:00" level=trace msg="sent dealer ping" Oct 31 22:40:00 volumiobpi go-librespot[2788]: time="2025-10-31T22:40:00-03:00" level=trace msg="received dealer pong" Oct 31 22:40:01 volumiobpi sudo[4275]: volumio : unable to resolve host volumiobpi Oct 31 22:40:01 volumiobpi sudo[4275]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 22:40:01 volumiobpi sudo[4275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-31 22:39 Oct 31 22:40:01 volumiobpi sudo[4275]: 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"