May 17 18:34:00 primo volumio[3561]: info: CoreCommandRouter::volumioGetQueue May 17 18:34:00 primo volumio[3561]: info: CoreStateMachine::getQueue May 17 18:34:00 primo volumio[3561]: info: CorePlayQueue::getQueue May 17 18:34:01 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:01.033+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 May 17 18:34:01 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. May 17 18:34:01 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:01 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:01 primo go-librespot[4511]: go-librespot daemon starting... May 17 18:34:01 primo go-librespot[4517]: time="2026-05-17T18:34:01+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:01 primo go-librespot[4517]: time="2026-05-17T18:34:01+01:00" level=debug msg="app state loaded" May 17 18:34:01 primo go-librespot[4517]: time="2026-05-17T18:34:01+01:00" level=debug msg="stored credentials not found" May 17 18:34:01 primo go-librespot[4517]: time="2026-05-17T18:34:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:02 primo go-librespot[4517]: time="2026-05-17T18:34:02+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:02+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:02 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:02 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:02 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:02 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:34:02 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 17 18:34:02 primo volumio[3561]: info: CoreCommandRouter::volumioPlay May 17 18:34:02 primo volumio[3561]: info: CoreStateMachine::play index 2 May 17 18:34:02 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:02 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:34:02 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:02 primo volumio[3561]: info: CoreStateMachine::play index undefined May 17 18:34:02 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:02 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:02 primo volumio[3561]: info: CoreStateMachine::startPlaybackTimer May 17 18:34:02 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:02 primo volumio[3561]: info: [1779039242432] ControllerSpotify::clearAddPlayTrack May 17 18:34:02 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/play May 17 18:34:02 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:02 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:02 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:04 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:04.342+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 May 17 18:34:04 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:04 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:04 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 17 18:34:04 primo volumio[3561]: info: CoreCommandRouter::volumioPlay May 17 18:34:04 primo volumio[3561]: info: CoreStateMachine::play index 2 May 17 18:34:04 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:04 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:34:04 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:04 primo volumio[3561]: info: CoreStateMachine::play index undefined May 17 18:34:04 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:04 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:04 primo volumio[3561]: info: CoreStateMachine::startPlaybackTimer May 17 18:34:04 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:04 primo volumio[3561]: info: [1779039244421] ControllerSpotify::clearAddPlayTrack May 17 18:34:04 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/play May 17 18:34:04 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:05 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. May 17 18:34:05 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:05 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:05 primo go-librespot[4546]: go-librespot daemon starting... May 17 18:34:05 primo go-librespot[4547]: time="2026-05-17T18:34:05+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:05 primo go-librespot[4547]: time="2026-05-17T18:34:05+01:00" level=debug msg="app state loaded" May 17 18:34:05 primo go-librespot[4547]: time="2026-05-17T18:34:05+01:00" level=debug msg="stored credentials not found" May 17 18:34:05 primo go-librespot[4547]: time="2026-05-17T18:34:05+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:05 primo go-librespot[4547]: time="2026-05-17T18:34:05+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:05+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:05 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:05 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:05 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:05 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:07 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:07.651+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 May 17 18:34:08 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. May 17 18:34:08 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:08 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:08 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:08 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:08 primo go-librespot[4554]: go-librespot daemon starting... May 17 18:34:08 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5, ...) May 17 18:34:08 primo go-librespot[4555]: time="2026-05-17T18:34:08+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:08 primo go-librespot[4555]: time="2026-05-17T18:34:08+01:00" level=debug msg="app state loaded" May 17 18:34:08 primo go-librespot[4555]: time="2026-05-17T18:34:08+01:00" level=debug msg="stored credentials not found" May 17 18:34:08 primo go-librespot[4555]: time="2026-05-17T18:34:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:09 primo go-librespot[4555]: time="2026-05-17T18:34:09+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:09+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:09 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:09 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/mcp/player0, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0001, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0001/char0002, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0001/char0004, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0001/char0006, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0001/char0008, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0014, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0014/char0015, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0014/char0017, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0014/char0019, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0029, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0029/desc002b, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char002c, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char002c/desc002e, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char002f, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char002f/desc0031, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0032, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0032/desc0034, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0035, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0035/desc0037, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0038, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0038/desc003a, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char003b, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char003b/desc003d, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char003e, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char003e/desc0040, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0041, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0043, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0043/desc0045, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0046, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0046/desc0048, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0049, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char0049/desc004b, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0028/char004c, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char005b, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char005b/desc005d, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char005e, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0060, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0060/desc0062, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0063, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0063/desc0065, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0066, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0066/desc0068, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0069, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char006b, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char006b/desc006d, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char006e, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char006e/desc0070, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0071, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0071/desc0073, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0074, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0076, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0076/desc0078, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0079, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char0079/desc007b, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char007c, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service005a/char007c/desc007e, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0082, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0082/char0083, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0090, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0090/char0091, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0093, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0093/char0094, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0093/char0094/desc0096, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0093/char0097, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service0093/char0097/desc0099, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service009a, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service009a/char009b, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service009a/char009b/desc009d, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service009e, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service009e/char009f, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service009e/char009f/desc00a1, ...) May 17 18:34:09 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/service009e/char00a2, ...) May 17 18:34:09 primo volumio[3561]: ------------------------------------ BT MESSAGE: [_watchMediaPlayer] Binding player for path: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5/mcp/player0 mac: 70:8F:68:4B:2E:E5 May 17 18:34:09 primo volumio[3561]: ------------------------------------ BT MESSAGE: activePlayer bound: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5/mcp/player0 May 17 18:34:10 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:10.958+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 May 17 18:34:11 primo upmpdcli[4564]: writing RSA key May 17 18:34:11 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:11 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.103+01:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.210+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=106.303291ms error="Head \"https://radio-directory.firebaseapp.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-07-20T15:01:16Z" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.252+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=http://pushupdates.volumio.org duration=146.37475ms May 17 18:34:12 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 17 18:34:12 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 17 18:34:12 primo volumio[3561]: info: Discovery: Getting this device information May 17 18:34:12 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.356+01:00 level=INFO msg="new address was allocated" component=ble/conn old=2 new=3 May 17 18:34:12 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:12 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 17 18:34:12 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. May 17 18:34:12 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:12 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:12 primo volumio[3561]: verbose: New Socket.io Connection to 192.168.1.111:3000 from 192.168.1.112 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 14 May 17 18:34:12 primo go-librespot[4568]: go-librespot daemon starting... May 17 18:34:12 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 17 18:34:12 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.404+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://google.com duration=300.341916ms error="Head \"https://google.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-08-10T08:37:35Z" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.418+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://www.googleapis.com duration=313.62825ms error="Head \"https://www.googleapis.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-08-10T08:39:04Z" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.420+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://securetoken.googleapis.com duration=313.903917ms error="Head \"https://securetoken.googleapis.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-08-10T08:39:04Z" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.419+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://database.volumio.cloud duration=310.378334ms error="Head \"https://database.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:12 primo go-librespot[4569]: time="2026-05-17T18:34:12+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:12 primo go-librespot[4569]: time="2026-05-17T18:34:12+01:00" level=debug msg="app state loaded" May 17 18:34:12 primo go-librespot[4569]: time="2026-05-17T18:34:12+01:00" level=debug msg="stored credentials not found" May 17 18:34:12 primo go-librespot[4569]: time="2026-05-17T18:34:12+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.439+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://functions.volumio.cloud duration=330.754667ms error="Head \"https://functions.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.446+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://functions.volumio.cloud duration=337.486459ms error="Head \"https://functions.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.452+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=346.832625ms error="Head \"https://browsing-performer.dfs.volumio.org\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-07-24T11:26:04Z" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.457+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=348.094167ms error="Head \"https://oauth-performer.dfs.volumio.org\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-07-08T11:28:45Z" May 17 18:34:12 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:12.498+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=392.070167ms error="Head \"https://myvolumio.firebaseio.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-07-06T15:01:47Z" May 17 18:34:12 primo dbus-daemon[2899]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.20" (uid=0 pid=3855 comm="/usr/bin/volumio5-onboarding" label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.6" (uid=0 pid=3428 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b" label="kernel") May 17 18:34:12 primo go-librespot[4569]: time="2026-05-17T18:34:12+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:12+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:12 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:12 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:13 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:13.076+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=http://cddb.volumio.org duration=969.317542ms May 17 18:34:13 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:13.136+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672 @ 0x18c33e0" latency=-2494h58m0.3526354s timeout=10s endpoint=http://plugins.volumio.org duration=1.028721876s May 17 18:34:14 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:14.336+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 May 17 18:34:14 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:14.673+01:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s May 17 18:34:14 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 17 18:34:14 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 17 18:34:14 primo volumio[3561]: info: Discovery: Getting this device information May 17 18:34:14 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:14 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:14 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 17 18:34:14 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:14.781+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=107.272667ms error="Head \"https://radio-directory.firebaseapp.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:14+01:00 is before 2026-07-20T15:01:16Z" May 17 18:34:14 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:14.822+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=http://pushupdates.volumio.org duration=146.463042ms May 17 18:34:14 primo volumio[3561]: verbose: New Socket.io Connection to 192.168.1.111:3000 from 192.168.1.112 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 14 May 17 18:34:14 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 17 18:34:14 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 17 18:34:14 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:14 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:14 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:14.971+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://google.com duration=292.763125ms error="Head \"https://google.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:14+01:00 is before 2026-08-10T08:37:35Z" May 17 18:34:14 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:14.980+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://securetoken.googleapis.com duration=305.589ms error="Head \"https://securetoken.googleapis.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:14+01:00 is before 2026-08-10T08:39:04Z" May 17 18:34:14 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:14.983+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://functions.volumio.cloud duration=309.09475ms error="Head \"https://functions.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:14+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:14 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:14.984+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://www.googleapis.com duration=304.712917ms error="Head \"https://www.googleapis.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:14+01:00 is before 2026-08-10T08:39:04Z" May 17 18:34:15 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:15.020+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://database.volumio.cloud duration=341.626708ms error="Head \"https://database.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:15+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:15 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:15.021+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://functions.volumio.cloud duration=342.48175ms error="Head \"https://functions.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:15+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:15 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:15.023+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=348.700334ms error="Head \"https://oauth-performer.dfs.volumio.org\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:15+01:00 is before 2026-07-08T11:28:45Z" May 17 18:34:15 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:15.027+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=350.596ms error="Head \"https://browsing-performer.dfs.volumio.org\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:15+01:00 is before 2026-07-24T11:26:04Z" May 17 18:34:15 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:15.066+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=387.525708ms error="Head \"https://myvolumio.firebaseio.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:15+01:00 is before 2026-07-06T15:01:47Z" May 17 18:34:15 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:15.254+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=http://cddb.volumio.org duration=576.958917ms May 17 18:34:15 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:15.381+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:53672,00:00:00:00:00:00%02 @ 0x18c33e0" latency=-2494h58m0.385508023s timeout=10s endpoint=http://plugins.volumio.org duration=705.210209ms May 17 18:34:15 primo bluetoothd[3428]: Device is already marked as connected May 17 18:34:15 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. May 17 18:34:15 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:15 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:15 primo go-librespot[4593]: go-librespot daemon starting... May 17 18:34:15 primo go-librespot[4594]: time="2026-05-17T18:34:15+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:15 primo go-librespot[4594]: time="2026-05-17T18:34:15+01:00" level=debug msg="app state loaded" May 17 18:34:15 primo go-librespot[4594]: time="2026-05-17T18:34:15+01:00" level=debug msg="stored credentials not found" May 17 18:34:15 primo go-librespot[4594]: time="2026-05-17T18:34:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:16 primo go-librespot[4594]: time="2026-05-17T18:34:16+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:16+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:16 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:16 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:17 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:17 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:18 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:18 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:18 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 17 18:34:18 primo volumio[3561]: info: CoreCommandRouter::volumioPlay May 17 18:34:18 primo volumio[3561]: info: CoreStateMachine::play index undefined May 17 18:34:18 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:18 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:18 primo volumio[3561]: info: CoreStateMachine::startPlaybackTimer May 17 18:34:18 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:18 primo volumio[3561]: info: [1779039258142] ControllerSpotify::clearAddPlayTrack May 17 18:34:18 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/play May 17 18:34:18 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:19 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. May 17 18:34:19 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:19 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:19 primo go-librespot[4601]: go-librespot daemon starting... May 17 18:34:19 primo go-librespot[4605]: time="2026-05-17T18:34:19+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:19 primo go-librespot[4605]: time="2026-05-17T18:34:19+01:00" level=debug msg="app state loaded" May 17 18:34:19 primo go-librespot[4605]: time="2026-05-17T18:34:19+01:00" level=debug msg="stored credentials not found" May 17 18:34:19 primo go-librespot[4605]: time="2026-05-17T18:34:19+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:19 primo go-librespot[4605]: time="2026-05-17T18:34:19+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:19+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:19 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:19 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:19 primo bluealsa[3440]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_41_86_21_56_9B_2E, ...) May 17 18:34:20 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:20 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:22 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. May 17 18:34:22 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:22 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:22 primo go-librespot[4617]: go-librespot daemon starting... May 17 18:34:22 primo go-librespot[4618]: time="2026-05-17T18:34:22+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:22 primo go-librespot[4618]: time="2026-05-17T18:34:22+01:00" level=debug msg="app state loaded" May 17 18:34:22 primo go-librespot[4618]: time="2026-05-17T18:34:22+01:00" level=debug msg="stored credentials not found" May 17 18:34:22 primo go-librespot[4618]: time="2026-05-17T18:34:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:23 primo go-librespot[4618]: time="2026-05-17T18:34:23+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:23+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:23 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:23 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:23 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:23 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:25 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:25 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:25 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 17 18:34:25 primo volumio[3561]: info: CoreCommandRouter::volumioPlay May 17 18:34:25 primo volumio[3561]: info: CoreStateMachine::play index 5 May 17 18:34:25 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:25 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:34:25 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:25 primo volumio[3561]: info: CoreStateMachine::play index undefined May 17 18:34:25 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:25 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:25 primo volumio[3561]: info: CoreStateMachine::startPlaybackTimer May 17 18:34:25 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:25 primo volumio[3561]: info: [1779039265417] ControllerSpotify::clearAddPlayTrack May 17 18:34:25 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/play May 17 18:34:25 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:26 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. May 17 18:34:26 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:26 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:26 primo go-librespot[4651]: go-librespot daemon starting... May 17 18:34:26 primo go-librespot[4652]: time="2026-05-17T18:34:26+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:26 primo go-librespot[4652]: time="2026-05-17T18:34:26+01:00" level=debug msg="app state loaded" May 17 18:34:26 primo go-librespot[4652]: time="2026-05-17T18:34:26+01:00" level=debug msg="stored credentials not found" May 17 18:34:26 primo go-librespot[4652]: time="2026-05-17T18:34:26+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:26 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:26 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:26 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 17 18:34:26 primo volumio[3561]: info: CoreCommandRouter::volumioPlay May 17 18:34:26 primo volumio[3561]: info: CoreStateMachine::play index 5 May 17 18:34:26 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:26 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:34:26 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:26 primo volumio[3561]: info: CoreStateMachine::play index undefined May 17 18:34:26 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:26 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:26 primo volumio[3561]: info: CoreStateMachine::startPlaybackTimer May 17 18:34:26 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:26 primo volumio[3561]: info: [1779039266643] ControllerSpotify::clearAddPlayTrack May 17 18:34:26 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/play May 17 18:34:26 primo go-librespot[4652]: time="2026-05-17T18:34:26+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:26+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:26 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 17 18:34:26 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:26 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:26 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:26 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:29 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. May 17 18:34:29 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:29 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:29 primo go-librespot[4659]: go-librespot daemon starting... May 17 18:34:29 primo go-librespot[4662]: time="2026-05-17T18:34:29+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:29 primo go-librespot[4662]: time="2026-05-17T18:34:29+01:00" level=debug msg="app state loaded" May 17 18:34:29 primo go-librespot[4662]: time="2026-05-17T18:34:29+01:00" level=debug msg="stored credentials not found" May 17 18:34:29 primo go-librespot[4662]: time="2026-05-17T18:34:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:29 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:29 primo go-librespot[4662]: time="2026-05-17T18:34:29+01:00" level=debug msg="new websocket client" May 17 18:34:29 primo volumio[3561]: info: Connection to go-librespot Websocket established May 17 18:34:30 primo go-librespot[4662]: time="2026-05-17T18:34:30+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:30+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:30 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:30 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:30 primo volumio[3561]: info: Connection to go-librespot Websocket closed May 17 18:34:32 primo volumio[3561]: info: Getting Spotify volume May 17 18:34:32 primo volumio[3561]: error: Failed to get Spotify volume from local API: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:32 primo volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 May 17 18:34:33 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:33 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:33 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:33 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:33 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. May 17 18:34:33 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:33 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:33 primo go-librespot[4676]: go-librespot daemon starting... May 17 18:34:33 primo go-librespot[4680]: time="2026-05-17T18:34:33+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:33 primo go-librespot[4680]: time="2026-05-17T18:34:33+01:00" level=debug msg="app state loaded" May 17 18:34:33 primo go-librespot[4680]: time="2026-05-17T18:34:33+01:00" level=debug msg="stored credentials not found" May 17 18:34:33 primo go-librespot[4680]: time="2026-05-17T18:34:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:33 primo go-librespot[4680]: time="2026-05-17T18:34:33+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:33+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:33 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:33 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:36 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:36 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:36 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. May 17 18:34:36 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:36 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:36 primo go-librespot[4711]: go-librespot daemon starting... May 17 18:34:36 primo go-librespot[4712]: time="2026-05-17T18:34:36+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:36 primo go-librespot[4712]: time="2026-05-17T18:34:36+01:00" level=debug msg="app state loaded" May 17 18:34:36 primo go-librespot[4712]: time="2026-05-17T18:34:36+01:00" level=debug msg="stored credentials not found" May 17 18:34:36 primo go-librespot[4712]: time="2026-05-17T18:34:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:37 primo go-librespot[4712]: time="2026-05-17T18:34:37+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:37+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:37 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:37 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:39 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:39 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:40 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. May 17 18:34:40 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:40 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:40 primo go-librespot[4719]: go-librespot daemon starting... May 17 18:34:40 primo go-librespot[4722]: time="2026-05-17T18:34:40+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:40 primo go-librespot[4722]: time="2026-05-17T18:34:40+01:00" level=debug msg="app state loaded" May 17 18:34:40 primo go-librespot[4722]: time="2026-05-17T18:34:40+01:00" level=debug msg="stored credentials not found" May 17 18:34:40 primo go-librespot[4722]: time="2026-05-17T18:34:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:40 primo go-librespot[4722]: time="2026-05-17T18:34:40+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:40+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:40 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:40 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:42 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:42 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:42.671+01:00 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.1.112:53672 error="read tcp 192.168.1.111:7331->192.168.1.112:53672: read: connection reset by peer" May 17 18:34:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:42.671+01:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.112:53672 May 17 18:34:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:42.672+01:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.112:53672 May 17 18:34:43 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. May 17 18:34:43 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:43 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:43 primo go-librespot[4735]: go-librespot daemon starting... May 17 18:34:43 primo go-librespot[4737]: time="2026-05-17T18:34:43+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:43 primo go-librespot[4737]: time="2026-05-17T18:34:43+01:00" level=debug msg="app state loaded" May 17 18:34:43 primo go-librespot[4737]: time="2026-05-17T18:34:43+01:00" level=debug msg="stored credentials not found" May 17 18:34:43 primo go-librespot[4737]: time="2026-05-17T18:34:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:43 primo volumio[3561]: verbose: New Socket.io Connection to 192.168.1.111 from 192.168.1.112 UA: Mozilla/5.0 (Linux; Android 16; SM-F966U1 Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.199 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::volumioGetVisibleSources May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:44 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 17 18:34:44 primo volumio[3561]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom May 17 18:34:44 primo volumio[3561]: info: Received Get System Info May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 17 18:34:44 primo volumio[3561]: info: Discovery: Getting this device information May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:44 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:44 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:44 primo volumio[3561]: info: Listing playlists May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::volumioGetQueue May 17 18:34:44 primo volumio[3561]: info: CoreStateMachine::getQueue May 17 18:34:44 primo volumio[3561]: info: CorePlayQueue::getQueue May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::getUIConfigOnPlugin May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::getUIConfigOnPlugin May 17 18:34:44 primo volumio[3561]: info: CoreCommandRouter::getUIConfigOnPlugin May 17 18:34:44 primo go-librespot[4737]: time="2026-05-17T18:34:44+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:44+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:44 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:44 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:44 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:44.765+01:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.112:58996 May 17 18:34:44 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:44.781+01:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s May 17 18:34:44 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:44.882+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=101.460375ms error="Head \"https://radio-directory.firebaseapp.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:44+01:00 is before 2026-07-20T15:01:16Z" May 17 18:34:44 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:44.930+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=http://pushupdates.volumio.org duration=146.116167ms May 17 18:34:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 17 18:34:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 17 18:34:45 primo volumio[3561]: info: Discovery: Getting this device information May 17 18:34:45 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:45 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 17 18:34:45 primo volumio[3561]: verbose: New Socket.io Connection to 192.168.1.111:3000 from 192.168.1.112 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 13 May 17 18:34:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 17 18:34:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.082+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://google.com duration=299.767959ms error="Head \"https://google.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-08-10T08:37:35Z" May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.095+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://securetoken.googleapis.com duration=309.833416ms error="Head \"https://securetoken.googleapis.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-08-10T08:39:04Z" May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.107+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://functions.volumio.cloud duration=321.198834ms error="Head \"https://functions.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.108+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://www.googleapis.com duration=326.399375ms error="Head \"https://www.googleapis.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-08-10T08:39:04Z" May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.114+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://functions.volumio.cloud duration=330.747834ms error="Head \"https://functions.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.114+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://database.volumio.cloud duration=328.861417ms error="Head \"https://database.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-07-02T14:14:43Z" May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.176+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=389.606375ms error="Head \"https://myvolumio.firebaseio.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-07-06T15:01:47Z" May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.195+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=413.048875ms error="Head \"https://oauth-performer.dfs.volumio.org\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-07-08T11:28:45Z" May 17 18:34:45 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:45 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.340+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=554.723208ms error="Head \"https://browsing-performer.dfs.volumio.org\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:45+01:00 is before 2026-07-24T11:26:04Z" May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.623+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=http://cddb.volumio.org duration=838.228542ms May 17 18:34:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:34:45.937+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%02,192.168.1.112:58996 @ 0x18c33e0" latency=-2494h58m0.386062134s timeout=10s endpoint=http://plugins.volumio.org duration=1.153128667s May 17 18:34:47 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. May 17 18:34:47 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:47 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:47 primo go-librespot[4770]: go-librespot daemon starting... May 17 18:34:47 primo go-librespot[4771]: time="2026-05-17T18:34:47+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:47 primo go-librespot[4771]: time="2026-05-17T18:34:47+01:00" level=debug msg="app state loaded" May 17 18:34:47 primo go-librespot[4771]: time="2026-05-17T18:34:47+01:00" level=debug msg="stored credentials not found" May 17 18:34:47 primo go-librespot[4771]: time="2026-05-17T18:34:47+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:47 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:47 primo volumio[3561]: info: CorePlayQueue::getTrack 5 May 17 18:34:47 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 17 18:34:47 primo volumio[3561]: info: CoreCommandRouter::volumioPlay May 17 18:34:47 primo go-librespot[4771]: time="2026-05-17T18:34:47+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:47+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:47 primo volumio[3561]: info: CoreStateMachine::play index 2 May 17 18:34:47 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:47 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:34:47 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:47 primo volumio[3561]: info: CoreStateMachine::play index undefined May 17 18:34:47 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:47 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:47 primo volumio[3561]: info: CoreStateMachine::startPlaybackTimer May 17 18:34:47 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:47 primo volumio[3561]: info: [1779039287726] ControllerSpotify::clearAddPlayTrack May 17 18:34:47 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/play May 17 18:34:47 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:47 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:47 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:48 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:48 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:49 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:49 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:49 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 17 18:34:49 primo volumio[3561]: info: CoreCommandRouter::volumioPlay May 17 18:34:49 primo volumio[3561]: info: CoreStateMachine::play index 2 May 17 18:34:49 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:49 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:34:49 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:49 primo volumio[3561]: info: CoreStateMachine::play index undefined May 17 18:34:49 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:49 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:49 primo volumio[3561]: info: CoreStateMachine::startPlaybackTimer May 17 18:34:49 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:49 primo volumio[3561]: info: [1779039289046] ControllerSpotify::clearAddPlayTrack May 17 18:34:49 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/play May 17 18:34:49 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:50 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. May 17 18:34:50 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:50 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:50 primo go-librespot[4778]: go-librespot daemon starting... May 17 18:34:50 primo go-librespot[4779]: time="2026-05-17T18:34:50+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:50 primo go-librespot[4779]: time="2026-05-17T18:34:50+01:00" level=debug msg="app state loaded" May 17 18:34:50 primo go-librespot[4779]: time="2026-05-17T18:34:50+01:00" level=debug msg="stored credentials not found" May 17 18:34:50 primo go-librespot[4779]: time="2026-05-17T18:34:50+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:51 primo go-librespot[4779]: time="2026-05-17T18:34:51+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:51+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:51 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:51 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:51 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:51 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:54 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:54 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:54 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:34:54 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:54 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 17 18:34:54 primo volumio[3561]: info: CoreCommandRouter::volumioPlay May 17 18:34:54 primo volumio[3561]: info: CoreStateMachine::play index undefined May 17 18:34:54 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:34:54 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:54 primo volumio[3561]: info: CoreStateMachine::startPlaybackTimer May 17 18:34:54 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:34:54 primo volumio[3561]: info: [1779039294287] ControllerSpotify::clearAddPlayTrack May 17 18:34:54 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/play May 17 18:34:54 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:54 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. May 17 18:34:54 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:54 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:54 primo go-librespot[4796]: go-librespot daemon starting... May 17 18:34:54 primo go-librespot[4799]: time="2026-05-17T18:34:54+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:54 primo go-librespot[4799]: time="2026-05-17T18:34:54+01:00" level=debug msg="app state loaded" May 17 18:34:54 primo go-librespot[4799]: time="2026-05-17T18:34:54+01:00" level=debug msg="stored credentials not found" May 17 18:34:54 primo go-librespot[4799]: time="2026-05-17T18:34:54+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:54 primo go-librespot[4799]: time="2026-05-17T18:34:54+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:54+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:54 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:54 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:34:57 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:34:57 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:34:57 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. May 17 18:34:57 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:57 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:34:57 primo go-librespot[4829]: go-librespot daemon starting... May 17 18:34:57 primo go-librespot[4830]: time="2026-05-17T18:34:57+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:34:57 primo go-librespot[4830]: time="2026-05-17T18:34:57+01:00" level=debug msg="app state loaded" May 17 18:34:57 primo go-librespot[4830]: time="2026-05-17T18:34:57+01:00" level=debug msg="stored credentials not found" May 17 18:34:57 primo go-librespot[4830]: time="2026-05-17T18:34:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:34:58 primo go-librespot[4830]: time="2026-05-17T18:34:58+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:34:58+01:00 is before 2026-07-09T00:00:00Z" May 17 18:34:58 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:34:58 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:00 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:00 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:01 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. May 17 18:35:01 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:01 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:01 primo go-librespot[4838]: go-librespot daemon starting... May 17 18:35:01 primo go-librespot[4839]: time="2026-05-17T18:35:01+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:01 primo go-librespot[4839]: time="2026-05-17T18:35:01+01:00" level=debug msg="app state loaded" May 17 18:35:01 primo go-librespot[4839]: time="2026-05-17T18:35:01+01:00" level=debug msg="stored credentials not found" May 17 18:35:01 primo go-librespot[4839]: time="2026-05-17T18:35:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:01 primo go-librespot[4839]: time="2026-05-17T18:35:01+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:01+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:01 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:01 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:03 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:03 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:04 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33. May 17 18:35:04 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:04 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:04 primo go-librespot[4855]: go-librespot daemon starting... May 17 18:35:04 primo go-librespot[4856]: time="2026-05-17T18:35:04+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:04 primo go-librespot[4856]: time="2026-05-17T18:35:04+01:00" level=debug msg="app state loaded" May 17 18:35:04 primo go-librespot[4856]: time="2026-05-17T18:35:04+01:00" level=debug msg="stored credentials not found" May 17 18:35:04 primo go-librespot[4856]: time="2026-05-17T18:35:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:05 primo go-librespot[4856]: time="2026-05-17T18:35:05+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:05+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:05 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:05 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:06 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:06 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:08 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34. May 17 18:35:08 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:08 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:08 primo go-librespot[4893]: go-librespot daemon starting... May 17 18:35:08 primo go-librespot[4894]: time="2026-05-17T18:35:08+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:08 primo go-librespot[4894]: time="2026-05-17T18:35:08+01:00" level=debug msg="app state loaded" May 17 18:35:08 primo go-librespot[4894]: time="2026-05-17T18:35:08+01:00" level=debug msg="stored credentials not found" May 17 18:35:08 primo go-librespot[4894]: time="2026-05-17T18:35:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:08 primo go-librespot[4894]: time="2026-05-17T18:35:08+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:08+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:08 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:08 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:09 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:09 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:11 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. May 17 18:35:11 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:11 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:11 primo go-librespot[4909]: go-librespot daemon starting... May 17 18:35:11 primo go-librespot[4910]: time="2026-05-17T18:35:11+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:11 primo go-librespot[4910]: time="2026-05-17T18:35:11+01:00" level=debug msg="app state loaded" May 17 18:35:11 primo go-librespot[4910]: time="2026-05-17T18:35:11+01:00" level=debug msg="stored credentials not found" May 17 18:35:11 primo go-librespot[4910]: time="2026-05-17T18:35:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:12 primo go-librespot[4910]: time="2026-05-17T18:35:12+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:12+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:12 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:12 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:12 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:12 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:15 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:15 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:15 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. May 17 18:35:15 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:15 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:15 primo go-librespot[4942]: go-librespot daemon starting... May 17 18:35:15 primo go-librespot[4943]: time="2026-05-17T18:35:15+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:15 primo go-librespot[4943]: time="2026-05-17T18:35:15+01:00" level=debug msg="app state loaded" May 17 18:35:15 primo go-librespot[4943]: time="2026-05-17T18:35:15+01:00" level=debug msg="stored credentials not found" May 17 18:35:15 primo go-librespot[4943]: time="2026-05-17T18:35:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:15 primo go-librespot[4943]: time="2026-05-17T18:35:15+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:15+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:15 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:15 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo upmpdcli[3885]: ThreadPool::addJob: too many jobs: 1000 May 17 18:35:18 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:18 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:18 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37. May 17 18:35:18 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:18 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:18 primo go-librespot[4969]: go-librespot daemon starting... May 17 18:35:18 primo go-librespot[4970]: time="2026-05-17T18:35:18+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:18 primo go-librespot[4970]: time="2026-05-17T18:35:18+01:00" level=debug msg="app state loaded" May 17 18:35:18 primo go-librespot[4970]: time="2026-05-17T18:35:18+01:00" level=debug msg="stored credentials not found" May 17 18:35:18 primo go-librespot[4970]: time="2026-05-17T18:35:18+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:19 primo go-librespot[4970]: time="2026-05-17T18:35:19+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:19+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:19 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:19 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:21 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:21 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:22 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38. May 17 18:35:22 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:22 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:22 primo go-librespot[4978]: go-librespot daemon starting... May 17 18:35:22 primo go-librespot[4984]: time="2026-05-17T18:35:22+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:22 primo go-librespot[4984]: time="2026-05-17T18:35:22+01:00" level=debug msg="app state loaded" May 17 18:35:22 primo go-librespot[4984]: time="2026-05-17T18:35:22+01:00" level=debug msg="stored credentials not found" May 17 18:35:22 primo go-librespot[4984]: time="2026-05-17T18:35:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:22 primo go-librespot[4984]: time="2026-05-17T18:35:22+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:22+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:22 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:22 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:24 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:24 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:25 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39. May 17 18:35:25 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:25 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:25 primo go-librespot[5014]: go-librespot daemon starting... May 17 18:35:25 primo go-librespot[5015]: time="2026-05-17T18:35:25+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:25 primo go-librespot[5015]: time="2026-05-17T18:35:25+01:00" level=debug msg="app state loaded" May 17 18:35:25 primo go-librespot[5015]: time="2026-05-17T18:35:25+01:00" level=debug msg="stored credentials not found" May 17 18:35:25 primo go-librespot[5015]: time="2026-05-17T18:35:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:26 primo go-librespot[5015]: time="2026-05-17T18:35:26+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:26+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:26 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:26 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:27 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:27 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:29 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 40. May 17 18:35:29 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:29 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:29 primo go-librespot[5022]: go-librespot daemon starting... May 17 18:35:29 primo go-librespot[5025]: time="2026-05-17T18:35:29+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:29 primo go-librespot[5025]: time="2026-05-17T18:35:29+01:00" level=debug msg="app state loaded" May 17 18:35:29 primo go-librespot[5025]: time="2026-05-17T18:35:29+01:00" level=debug msg="stored credentials not found" May 17 18:35:29 primo go-librespot[5025]: time="2026-05-17T18:35:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:29 primo go-librespot[5025]: time="2026-05-17T18:35:29+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:29+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:29 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:29 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:30 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:30 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:32 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 41. May 17 18:35:32 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:32 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:32 primo go-librespot[5038]: go-librespot daemon starting... May 17 18:35:32 primo go-librespot[5040]: time="2026-05-17T18:35:32+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:32 primo go-librespot[5040]: time="2026-05-17T18:35:32+01:00" level=debug msg="app state loaded" May 17 18:35:32 primo go-librespot[5040]: time="2026-05-17T18:35:32+01:00" level=debug msg="stored credentials not found" May 17 18:35:32 primo go-librespot[5040]: time="2026-05-17T18:35:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:33 primo go-librespot[5040]: time="2026-05-17T18:35:33+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:33+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:33 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:33 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:33 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:33 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:33 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:33.616+01:00 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.1.112:58996 error="read tcp 192.168.1.111:7331->192.168.1.112:58996: read: connection reset by peer" May 17 18:35:33 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:33.617+01:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.112:58996 May 17 18:35:33 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:33.617+01:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.112:58996 May 17 18:35:36 primo bluetoothd[3428]: Device is already marked as connected May 17 18:35:36 primo volumiobt[4020]: 2026-05-17 18:35:36 a2dp-agent [INFO] AuthorizeService - Device: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5, UUID: 0000110d-0000-1000-8000-00805f9b34fb May 17 18:35:36 primo volumiobt[4020]: 2026-05-17 18:35:36 a2dp-agent [INFO] Authorized audio service from device: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5 May 17 18:35:36 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:36 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 42. May 17 18:35:36 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:36 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:36 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/fd0, ...) May 17 18:35:36 primo bluealsa[3440]: ../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/sink/1 May 17 18:35:36 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:36 primo bluealsa[3440]: ../src/a2dp-sbc.c:536: SBC: Selected bit-pool range: [2, 53] May 17 18:35:36 primo bluealsa[3440]: ../src/storage.c:123: Loading storage: /var/lib/bluealsa/70:8F:68:4B:2E:E5 May 17 18:35:36 primo bluealsa[3440]: bluez.c:572: A2DP Sink (SBC) configured for device 70:8F:68:4B:2E:E5 May 17 18:35:36 primo bluealsa[3440]: bluez.c:575: A2DP selected configuration blob [len=4]: 21150235 May 17 18:35:36 primo bluealsa[3440]: bluez.c:577: PCM configuration: channels: 2, sampling: 44100 May 17 18:35:36 primo bluealsa[3440]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/3 May 17 18:35:36 primo go-librespot[5072]: go-librespot daemon starting... May 17 18:35:36 primo bluetoothd[3428]: Endpoint registered: sender=:1.7 path=/org/bluez/hci0/A2DP/SBC/sink/3 May 17 18:35:36 primo go-librespot[5074]: time="2026-05-17T18:35:36+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:36 primo go-librespot[5074]: time="2026-05-17T18:35:36+01:00" level=debug msg="app state loaded" May 17 18:35:36 primo go-librespot[5074]: time="2026-05-17T18:35:36+01:00" level=debug msg="stored credentials not found" May 17 18:35:36 primo volumio[3561]: ------------------------------------ BT MESSAGE: [DEBUG] registerVolumeHandler: MAC = 70:8F:68:4B:2E:E5, rawVolume = 127 May 17 18:35:36 primo volumio[3561]: ------------------------------------ BT MESSAGE: Initial volume cap applied for 70:8F:68:4B:2E:E5: 75 (cap 75%) May 17 18:35:36 primo volumio[3561]: ------------------------------------ BT MESSAGE: Received volume: raw = 127, scaled = 75 May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: inputs , alsavolume May 17 18:35:36 primo go-librespot[5074]: time="2026-05-17T18:35:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:36 primo volumio[3561]: ------------------------------------ BT MESSAGE: [WARN] pushMultiRoomVolume is not available May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: inputs , alsavolume May 17 18:35:36 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:36 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:36 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:35:36 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:36 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:36 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:36 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:36 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:35:36 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:36 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.455+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=42092 volume=75 May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.455+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=42092 volume=75 May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.457+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=42092 volume=75 May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.457+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=42092 volume=75 May 17 18:35:36 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:36 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:36 primo volumio[3561]: info: Setting Spotify Volume from Volumio: 75 May 17 18:35:36 primo volumio[3561]: ------------------------------------ BT MESSAGE: [dbus-next] Playback state changed: false from 70:8F:68:4B:2E:E5 May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.534+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:4qnRzzrj3CCGDFCqyA1TqC title=Você May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.535+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" id=spotify:track:4qnRzzrj3CCGDFCqyA1TqC title=Você May 17 18:35:36 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:36 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:36 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:35:36 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:36 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.557+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=42092 volume=75 May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.558+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=42092 volume=75 May 17 18:35:36 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:36 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:36 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:36 primo volumio[3561]: info: CorePlayQueue::getTrack 2 May 17 18:35:36 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:36 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.577+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=42092 volume=75 May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.577+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=42092 volume=75 May 17 18:35:36 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:36 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.715+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:4qnRzzrj3CCGDFCqyA1TqC title=Você May 17 18:35:36 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:36.716+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" id=spotify:track:4qnRzzrj3CCGDFCqyA1TqC title=Você May 17 18:35:36 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep1, ...) May 17 18:35:36 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: SBC May 17 18:35:36 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep2, ...) May 17 18:35:36 primo go-librespot[5074]: time="2026-05-17T18:35:36+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:36+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:36 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: AAC May 17 18:35:36 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep3, ...) May 17 18:35:36 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: aptX May 17 18:35:36 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep4, ...) May 17 18:35:36 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: LDAC May 17 18:35:36 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep5, ...) May 17 18:35:36 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: samsung-SC May 17 18:35:36 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:36 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:36 primo bluealsa[3440]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State May 17 18:35:36 primo bluetoothd[3428]: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5/fd0: fd(28) ready May 17 18:35:36 primo bluealsa[3440]: ../src/ba-transport.c:319: New A2DP transport: 15 May 17 18:35:36 primo volumio[3561]: ------------------------------------ BT MESSAGE: Debounce: dropped pending playback=false for 70:8F:68:4B:2E:E5 (true arrived within window) May 17 18:35:36 primo bluealsa[3440]: ../src/ba-transport.c:320: A2DP socket MTU: 15: R:672 W:1024 May 17 18:35:36 primo bluealsa[3440]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State May 17 18:35:36 primo bluealsa[3440]: ../src/ba-transport.c:1075: Starting transport: A2DP Sink (SBC) May 17 18:35:36 primo bluealsa[3440]: ../src/ba-transport-pcm.c:294: Created BT socket duplicate: [15]: 16 May 17 18:35:36 primo bluealsa[3440]: ../src/ba-transport-pcm.c:373: Created new IO thread [ba-a2dp-sbc]: A2DP Sink (SBC) May 17 18:35:36 primo bluealsa[3440]: ../src/a2dp-sbc.c:331: PCM IO loop: START: a2dp_sbc_dec_thread: A2DP Sink (SBC) May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: [dbus-next] Playback state changed: true from 70:8F:68:4B:2E:E5 May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: setWinningMac: 70:8F:68:4B:2E:E5 May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: Playback started, enabling output (party mode: last play wins) May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::volumioStop May 17 18:35:37 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:35:37 primo volumio[3561]: info: CoreStateMachine::serviceStop May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::serviceStop May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: [FUNC] stop May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: [dbus-next] Disabling Bluetooth Audio Output May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: Bluetooth audio output stopped May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: [AAMP] Modular pipeline enabled - forcing ALSA route: volumioLocalPlayback May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: Party mode: using preferred BT MAC: 70:8F:68:4B:2E:E5 May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: Spawning bluealsa-aplay with args: --profile-a2dp --pcm=volumioLocalPlayback --pcm-buffer-time=500000 --pcm-period-time=100000 70:8F:68:4B:2E:E5 May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: [metaCache] Failed to load cache file for 70:8F:68:4B:2E:E5: Error: ENOENT: no such file or directory, open '/tmp/bluetooth-cache/meta-70:8F:68:4B:2E:E5.json' May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:37 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:37 primo bluealsa[3440]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_70_8F_68_4B_2E_E5/a2dpsnk/source May 17 18:35:37 primo bluealsa[3440]: ../src/codec-sbc.c:278: SBC setup: 44100 Hz JointStereo allocation=Loudness blocks=16 sub-bands=8 bit-pool=53 => 327993 bps May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:37 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:37 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:37 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:37 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:37 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:37 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.075+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=75 May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.076+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=75 May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.077+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=75 May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.077+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=75 May 17 18:35:37 primo kernel: aml_tdm_open May 17 18:35:37 primo kernel: Not init audio effects May 17 18:35:37 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 May 17 18:35:37 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk May 17 18:35:37 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk May 17 18:35:37 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 May 17 18:35:37 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc0501bf818, id(1), clksel(1) May 17 18:35:37 primo kernel: aml_dai_set_tdm_fmt(), fmt not change May 17 18:35:37 primo kernel: dump_pcm_setting(ffffffc0501bf818) May 17 18:35:37 primo kernel: pcm_mode(1) May 17 18:35:37 primo kernel: sysclk(11289600) May 17 18:35:37 primo kernel: sysclk_bclk_ratio(4) May 17 18:35:37 primo kernel: bclk(2822400) May 17 18:35:37 primo kernel: bclk_lrclk_ratio(64) May 17 18:35:37 primo kernel: lrclk(44100) May 17 18:35:37 primo kernel: tx_mask(0x3) May 17 18:35:37 primo kernel: rx_mask(0x3) May 17 18:35:37 primo kernel: slots(2) May 17 18:35:37 primo kernel: slot_width(32) May 17 18:35:37 primo kernel: lane_mask_in(0x2) May 17 18:35:37 primo kernel: lane_mask_out(0x1) May 17 18:35:37 primo kernel: lane_oe_mask_in(0x0) May 17 18:35:37 primo kernel: lane_oe_mask_out(0x0) May 17 18:35:37 primo kernel: lane_lb_mask_in(0x0) May 17 18:35:37 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk May 17 18:35:37 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk May 17 18:35:37 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 May 17 18:35:37 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) May 17 18:35:37 primo kernel: aml_dai_set_bclk_ratio, select I2S mode May 17 18:35:37 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B May 17 18:35:37 primo kernel: aml_tdm_prepare(), reset fddr May 17 18:35:37 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 May 17 18:35:37 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 May 17 18:35:37 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 May 17 18:35:37 primo kernel: tdm playback mute: 0, lane_cnt = 8 May 17 18:35:37 primo volumio[3561]: info: FusionDsp - Volumio is playing May 17 18:35:37 primo volumio[3561]: warn: FusionDsp - Monitor WebSocket not open, skipping commands May 17 18:35:37 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:37 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:37 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:37 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:37 primo volumio[3561]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [5082] D: aplay.c:904: Creating IO worker 70:8F:68:4B:2E:E5 May 17 18:35:37 primo volumio[3561]: bluealsa-aplay: [5082] D: aplay.c:1320: Starting main loop May 17 18:35:37 primo volumio[3561]: bluealsa-aplay: [5083] D: aplay.c:577: Opening BlueALSA source PCM: /org/bluealsa/hci0/dev_70_8F_68_4B_2E_E5/a2dpsnk/source May 17 18:35:37 primo volumio[3561]: bluealsa-aplay: [5083] D: aplay.c:603: Starting IO loop May 17 18:35:37 primo volumio[3561]: bluealsa-aplay: [5083] D: aplay.c:732: Opening ALSA playback PCM: name=volumioLocalPlayback channels=2 rate=44100 May 17 18:35:37 primo volumio[3561]: bluealsa-aplay: [5083] D: aplay.c:339: Opening ALSA mixer: name=default elem=Master index=0 May 17 18:35:37 primo volumio[3561]: bluealsa-aplay: [5083] W: aplay.c:350: Couldn't open ALSA mixer: Mixer element not found May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.135+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:4qnRzzrj3CCGDFCqyA1TqC title=Você May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.136+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" id=spotify:track:4qnRzzrj3CCGDFCqyA1TqC title=Você May 17 18:35:37 primo volumio[3561]: info: FusionDsp - Clipping Monitor started May 17 18:35:37 primo volumio[3561]: info: MCU Signalled Playback Active May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.255+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:4qnRzzrj3CCGDFCqyA1TqC title=Você May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.256+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" id=spotify:track:4qnRzzrj3CCGDFCqyA1TqC title=Você May 17 18:35:37 primo volumio[3561]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 17 18:35:37 primo volumio[3561]: info: FusionDsp - ---- read samplerate from file: 44100 May 17 18:35:37 primo kernel: asoc-aml-card auge_sound: tdm playback enable May 17 18:35:37 primo kernel: spdif_a is set to enable May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.555+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title= May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.556+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" id= title= May 17 18:35:37 primo volumio[3561]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.675+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title= May 17 18:35:37 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:37.676+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" id= title= May 17 18:35:37 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/volume May 17 18:35:37 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:39 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:39 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:39 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 43. May 17 18:35:39 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:39 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:39 primo go-librespot[5095]: go-librespot daemon starting... May 17 18:35:39 primo go-librespot[5096]: time="2026-05-17T18:35:39+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:39 primo go-librespot[5096]: time="2026-05-17T18:35:39+01:00" level=debug msg="app state loaded" May 17 18:35:39 primo go-librespot[5096]: time="2026-05-17T18:35:39+01:00" level=debug msg="stored credentials not found" May 17 18:35:39 primo go-librespot[5096]: time="2026-05-17T18:35:39+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: Fallback: pushing metadata after resume May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.087+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=75 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.088+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=75 May 17 18:35:40 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5, ...) May 17 18:35:40 primo volumiobt[4020]: 2026-05-17 18:35:40 a2dp-agent [INFO] AuthorizeService - Device: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5, UUID: 0000110e-0000-1000-8000-00805f9b34fb May 17 18:35:40 primo volumiobt[4020]: 2026-05-17 18:35:40 a2dp-agent [INFO] Authorized audio service from device: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5 May 17 18:35:40 primo kernel: input: Z Fold7 de Gabriel (AVRCP) as /devices/virtual/input/input6 May 17 18:35:40 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/avrcp/player0, ...) May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: [_watchMediaPlayer] Binding player for path: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5/avrcp/player0 mac: 70:8F:68:4B:2E:E5 May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: activePlayer bound: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5/avrcp/player0 May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo go-librespot[5096]: time="2026-05-17T18:35:40+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:40+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.280+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=75 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.281+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=75 May 17 18:35:40 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:40 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:40 primo bluealsa[3440]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Volume May 17 18:35:40 primo bluealsa[3440]: bluez.c:1502: Updating A2DP volume: 77 [-7.21 dB] May 17 18:35:40 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: [DEBUG] registerVolumeHandler: MAC = 70:8F:68:4B:2E:E5, rawVolume = 77 May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: Received volume: raw = 77, scaled = 61 May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: inputs , alsavolume May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: [WARN] pushMultiRoomVolume is not available May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: inputs , alsavolume May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.342+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.342+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.343+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.343+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo systemd[1]: Stopping triggerhappy.service - triggerhappy global hotkey daemon... May 17 18:35:40 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:40 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo volumio[3561]: info: Setting Spotify Volume from Volumio: 61 May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.462+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.462+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.477+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.478+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:40 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: Received new metadata for 70:8F:68:4B:2E:E5 May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: [metaCache] Saved metadata to /tmp/bluetooth-cache/meta-70:8F:68:4B:2E:E5.json May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.545+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.545+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.562+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136462 volume=61 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.562+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=136462 volume=61 May 17 18:35:40 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:40 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo bluealsa[3440]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/avrcp/player0, ...) May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: setWinningMac: none May 17 18:35:40 primo volumio[3561]: [106B blob data] May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: [FUNC] detachBluetooth May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: [dbus-next] Disabling Bluetooth Audio Output May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: Killing bluealsa-aplay process May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: Bluetooth audio output disabled. May 17 18:35:40 primo volumio[3561]: verbose: UNSET VOLATILE: Service: bluetooth May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::resetVolumioState May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::getcurrentVolume May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioRetrievevolume May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: inputs , retrievevolume May 17 18:35:40 primo systemd[1]: triggerhappy.service: Deactivated successfully. May 17 18:35:40 primo bluealsa[3440]: ../src/ba-transport-pcm.c:453: Closing PCM: 18 May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:40 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:40 primo systemd[1]: Stopped triggerhappy.service - triggerhappy global hotkey daemon. May 17 18:35:40 primo bluealsa[3440]: ../src/ba-transport.c:203: PCM clients check keep-alive: 0 ms May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:40 primo systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... May 17 18:35:40 primo bluealsa[3440]: ../src/ba-transport-pcm.c:307: Closing BT socket duplicate [15]: 16 May 17 18:35:40 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:40 primo bluealsa[3440]: ../src/a2dp-sbc.c:392: PCM IO loop: EXIT: a2dp_sbc_dec_thread: A2DP Sink (SBC) May 17 18:35:40 primo bluealsa[3440]: ../src/ba-transport.c:346: Releasing A2DP transport: 15 May 17 18:35:40 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:40 primo volumio[3561]: info: CoreCommandRouter::volumioStop May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:35:40 primo volumio[3561]: info: CoreStateMachine::setConsumeUpdateService undefined May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.653+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=0 volume=61 May 17 18:35:40 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:40.653+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=0 volume=61 May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: Detached Bluetooth after transport removal May 17 18:35:40 primo volumio[3561]: info: FusionDsp - Volumio is not playing May 17 18:35:40 primo volumio[3561]: info: FusionDsp - Clipped samples monitor stopped May 17 18:35:40 primo bluealsa[3440]: ../src/ba-transport.c:381: Closing A2DP transport: 15 May 17 18:35:40 primo bluealsa[3440]: ../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.ClearConfiguration() on /org/bluez/hci0/A2DP/SBC/sink/1 May 17 18:35:40 primo bluealsa[3440]: bluez.c:615: Disconnecting media endpoint: /org/bluez/hci0/A2DP/SBC/sink/1 May 17 18:35:40 primo bluealsa[3440]: ../src/ba-transport-pcm.c:257: Exiting IO thread [ba-a2dp-sbc]: A2DP Sink (SBC) May 17 18:35:40 primo bluealsa[3440]: ../src/ba-transport.c:826: Freeing transport: A2DP Sink (SBC) May 17 18:35:40 primo bluealsa[3440]: ../src/storage.c:160: Saving storage: /var/lib/bluealsa/70:8F:68:4B:2E:E5 May 17 18:35:40 primo bluealsa[3440]: ../src/ba-device.c:143: Freeing device: 70:8F:68:4B:2E:E5 May 17 18:35:40 primo bluealsa[3440]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/fd0, ...) May 17 18:35:40 primo bluealsa[3440]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep1, ...) May 17 18:35:40 primo bluealsa[3440]: bluez.c:1428: Removing Stream End-Point: 70:8F:68:4B:2E:E5: SRC: SBC May 17 18:35:40 primo bluealsa[3440]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep2, ...) May 17 18:35:40 primo bluealsa[3440]: bluez.c:1428: Removing Stream End-Point: 70:8F:68:4B:2E:E5: SRC: AAC May 17 18:35:40 primo bluealsa[3440]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep3, ...) May 17 18:35:40 primo thd[5105]: Unable to parse trigger line: May 17 18:35:40 primo thd[5105]: Unable to parse trigger line: May 17 18:35:40 primo thd[5105]: Unable to parse trigger line: May 17 18:35:40 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:40 primo bluealsa[3440]: bluez.c:1428: Removing Stream End-Point: 70:8F:68:4B:2E:E5: SRC: aptX May 17 18:35:40 primo bluealsa[3440]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep4, ...) May 17 18:35:40 primo bluealsa[3440]: bluez.c:1428: Removing Stream End-Point: 70:8F:68:4B:2E:E5: SRC: LDAC May 17 18:35:40 primo bluealsa[3440]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep5, ...) May 17 18:35:40 primo bluealsa[3440]: bluez.c:1428: Removing Stream End-Point: 70:8F:68:4B:2E:E5: SRC: samsung-SC May 17 18:35:40 primo systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. May 17 18:35:40 primo volumio[3561]: ------------------------------------ BT MESSAGE: bluealsa-aplay exited with code null, signal SIGKILL May 17 18:35:40 primo systemd-logind[2909]: Failed to open /dev/input/event5: No such file or directory May 17 18:35:40 primo systemd[1]: Stopping triggerhappy.service - triggerhappy global hotkey daemon... May 17 18:35:40 primo volumio[3561]: info: MCU Signalled Playback Inactive May 17 18:35:40 primo systemd[1]: triggerhappy.service: Deactivated successfully. May 17 18:35:40 primo systemd[1]: Stopped triggerhappy.service - triggerhappy global hotkey daemon. May 17 18:35:40 primo systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... May 17 18:35:40 primo thd[5107]: Unable to parse trigger line: May 17 18:35:40 primo thd[5107]: Unable to parse trigger line: May 17 18:35:40 primo thd[5107]: Unable to parse trigger line: May 17 18:35:40 primo systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. May 17 18:35:40 primo kernel: asoc-aml-card auge_sound: tdm playback stop May 17 18:35:40 primo kernel: spdif_a is set to disable May 17 18:35:40 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 May 17 18:35:40 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B May 17 18:35:40 primo kernel: tdm playback mute: 1, lane_cnt = 8 May 17 18:35:40 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 May 17 18:35:40 primo volumio[3561]: info: camilladsp respawn in 100 ms (attempt 1/10) May 17 18:35:41 primo volumio[3561]: info: Sending Spotify command with payload to local API: /player/volume May 17 18:35:41 primo volumio[3561]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:42 primo volumiobt[4020]: 2026-05-17 18:35:42 a2dp-agent [INFO] AuthorizeService - Device: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5, UUID: 0000110d-0000-1000-8000-00805f9b34fb May 17 18:35:42 primo volumiobt[4020]: 2026-05-17 18:35:42 a2dp-agent [INFO] Authorized audio service from device: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5 May 17 18:35:42 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep1, ...) May 17 18:35:42 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: SBC May 17 18:35:42 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep2, ...) May 17 18:35:42 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: AAC May 17 18:35:42 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep3, ...) May 17 18:35:42 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: aptX May 17 18:35:42 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep4, ...) May 17 18:35:42 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: LDAC May 17 18:35:42 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/sep5, ...) May 17 18:35:42 primo bluealsa[3440]: bluez.c:1362: Adding new Stream End-Point: 70:8F:68:4B:2E:E5: SRC: samsung-SC May 17 18:35:42 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/fd1, ...) May 17 18:35:42 primo bluealsa[3440]: ../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/sink/1 May 17 18:35:42 primo bluealsa[3440]: ../src/a2dp-sbc.c:536: SBC: Selected bit-pool range: [2, 53] May 17 18:35:42 primo bluealsa[3440]: ../src/storage.c:123: Loading storage: /var/lib/bluealsa/70:8F:68:4B:2E:E5 May 17 18:35:42 primo bluealsa[3440]: bluez.c:572: A2DP Sink (SBC) configured for device 70:8F:68:4B:2E:E5 May 17 18:35:42 primo bluealsa[3440]: bluez.c:575: A2DP selected configuration blob [len=4]: 21150235 May 17 18:35:42 primo bluealsa[3440]: bluez.c:577: PCM configuration: channels: 2, sampling: 44100 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [DEBUG] registerVolumeHandler: MAC = 70:8F:68:4B:2E:E5, rawVolume = 77 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: Received volume: raw = 77, scaled = 61 May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: inputs , alsavolume May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [WARN] pushMultiRoomVolume is not available May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: inputs , alsavolume May 17 18:35:42 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:42 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:42 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:42 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:42 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:42 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.314+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=1770 volume=61 May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.314+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=1770 volume=61 May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.315+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=1770 volume=61 May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.315+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=1770 volume=61 May 17 18:35:42 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:42 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:42 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:42 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:42 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.352+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=1770 volume=61 May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.352+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=1770 volume=61 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [dbus-next] Playback state changed: false from 70:8F:68:4B:2E:E5 May 17 18:35:42 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:42 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:42 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:42 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:42 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:42 primo volumio[3561]: info: CorePlayQueue::getTrack 0 May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.415+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_STOPPED positionMs=1770 volume=61 May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.416+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_STOPPED positionMs=1770 volume=61 May 17 18:35:42 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:42 primo bluealsa[3440]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State May 17 18:35:42 primo bluetoothd[3428]: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5/fd1: fd(28) ready May 17 18:35:42 primo bluealsa[3440]: ../src/ba-transport.c:319: New A2DP transport: 15 May 17 18:35:42 primo bluealsa[3440]: ../src/ba-transport.c:320: A2DP socket MTU: 15: R:672 W:1024 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: Debounce: dropped pending playback=false for 70:8F:68:4B:2E:E5 (true arrived within window) May 17 18:35:42 primo bluealsa[3440]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State May 17 18:35:42 primo bluealsa[3440]: ../src/ba-transport.c:1075: Starting transport: A2DP Sink (SBC) May 17 18:35:42 primo bluealsa[3440]: ../src/ba-transport-pcm.c:294: Created BT socket duplicate: [15]: 16 May 17 18:35:42 primo bluealsa[3440]: ../src/a2dp-sbc.c:331: PCM IO loop: START: a2dp_sbc_dec_thread: A2DP Sink (SBC) May 17 18:35:42 primo bluealsa[3440]: ../src/ba-transport-pcm.c:373: Created new IO thread [ba-a2dp-sbc]: A2DP Sink (SBC) May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [dbus-next] Playback state changed: true from 70:8F:68:4B:2E:E5 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: setWinningMac: 70:8F:68:4B:2E:E5 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: Playback started, enabling output (party mode: last play wins) May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioStop May 17 18:35:42 primo volumio[3561]: info: CoreStateMachine::stop May 17 18:35:42 primo volumio[3561]: info: CoreStateMachine::serviceStop May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::serviceStop May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [FUNC] stop May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [dbus-next] Disabling Bluetooth Audio Output May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: Bluetooth audio output stopped May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [AAMP] Modular pipeline enabled - forcing ALSA route: volumioLocalPlayback May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: Party mode: using preferred BT MAC: 70:8F:68:4B:2E:E5 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: Spawning bluealsa-aplay with args: --profile-a2dp --pcm=volumioLocalPlayback --pcm-buffer-time=500000 --pcm-period-time=100000 70:8F:68:4B:2E:E5 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: [metaCache] Loaded metadata for 70:8F:68:4B:2E:E5 from memory May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: Loaded metadata from cache for 70:8F:68:4B:2E:E5 May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:42 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:42 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:42 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:42 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.761+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136462 volume=61 May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.761+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=136462 volume=61 May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.762+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136462 volume=61 May 17 18:35:42 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:42.762+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18c33e0" state=STATUS_PLAYING positionMs=136462 volume=61 May 17 18:35:42 primo bluealsa[3440]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_70_8F_68_4B_2E_E5/a2dpsnk/source May 17 18:35:42 primo volumio[3561]: info: FusionDsp - Volumio is playing May 17 18:35:42 primo volumio[3561]: warn: FusionDsp - Monitor WebSocket not open, skipping commands May 17 18:35:42 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:42 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:42 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:42 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [5113] D: aplay.c:904: Creating IO worker 70:8F:68:4B:2E:E5 May 17 18:35:42 primo volumio[3561]: bluealsa-aplay: [5113] D: aplay.c:1320: Starting main loop May 17 18:35:42 primo volumio[3561]: bluealsa-aplay: [5114] D: aplay.c:577: Opening BlueALSA source PCM: /org/bluealsa/hci0/dev_70_8F_68_4B_2E_E5/a2dpsnk/source May 17 18:35:42 primo volumio[3561]: bluealsa-aplay: [5114] D: aplay.c:603: Starting IO loop May 17 18:35:42 primo volumio[3561]: error: FusionDsp - Monitor WebSocket error: [object Object] May 17 18:35:42 primo volumio[3561]: info: FusionDsp - Clipping Monitor reconnecting in 2000ms May 17 18:35:42 primo bluealsa[3440]: ../src/codec-sbc.c:278: SBC setup: 44100 Hz JointStereo allocation=Loudness blocks=16 sub-bands=8 bit-pool=53 => 327993 bps May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [5114] D: aplay.c:732: Opening ALSA playback PCM: name=volumioLocalPlayback channels=2 rate=44100 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [5114] D: aplay.c:339: Opening ALSA mixer: name=default elem=Master index=0 May 17 18:35:42 primo volumio[3561]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [5114] W: aplay.c:350: Couldn't open ALSA mixer: Mixer element not found May 17 18:35:42 primo kernel: aml_tdm_open May 17 18:35:42 primo kernel: Not init audio effects May 17 18:35:42 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 May 17 18:35:42 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk May 17 18:35:42 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk May 17 18:35:42 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 May 17 18:35:42 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc0501bf818, id(1), clksel(1) May 17 18:35:42 primo kernel: aml_dai_set_tdm_fmt(), fmt not change May 17 18:35:42 primo kernel: dump_pcm_setting(ffffffc0501bf818) May 17 18:35:42 primo kernel: pcm_mode(1) May 17 18:35:42 primo kernel: sysclk(11289600) May 17 18:35:42 primo kernel: sysclk_bclk_ratio(4) May 17 18:35:42 primo kernel: bclk(2822400) May 17 18:35:42 primo kernel: bclk_lrclk_ratio(64) May 17 18:35:42 primo kernel: lrclk(44100) May 17 18:35:42 primo kernel: tx_mask(0x3) May 17 18:35:42 primo kernel: rx_mask(0x3) May 17 18:35:42 primo kernel: slots(2) May 17 18:35:42 primo kernel: slot_width(32) May 17 18:35:42 primo kernel: lane_mask_in(0x2) May 17 18:35:42 primo kernel: lane_mask_out(0x1) May 17 18:35:42 primo kernel: lane_oe_mask_in(0x0) May 17 18:35:42 primo kernel: lane_oe_mask_out(0x0) May 17 18:35:42 primo kernel: lane_lb_mask_in(0x0) May 17 18:35:42 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk May 17 18:35:42 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk May 17 18:35:42 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 May 17 18:35:42 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) May 17 18:35:42 primo kernel: aml_dai_set_bclk_ratio, select I2S mode May 17 18:35:42 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B May 17 18:35:42 primo kernel: aml_tdm_prepare(), reset fddr May 17 18:35:42 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 May 17 18:35:42 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 May 17 18:35:42 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 May 17 18:35:42 primo kernel: tdm playback mute: 0, lane_cnt = 8 May 17 18:35:42 primo volumio[3561]: info: MCU Signalled Playback Active May 17 18:35:43 primo volumio[3561]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 17 18:35:43 primo volumio[3561]: info: FusionDsp - ---- read samplerate from file: 44100 May 17 18:35:43 primo volumio[3561]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 17 18:35:43 primo kernel: asoc-aml-card auge_sound: tdm playback enable May 17 18:35:43 primo kernel: spdif_a is set to enable May 17 18:35:43 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 44. May 17 18:35:43 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:43 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:43 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:43.395+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 May 17 18:35:43 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:43.396+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%02 @ 0x18c33e0" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" May 17 18:35:43 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:43.396+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title= May 17 18:35:43 primo go-librespot[5123]: go-librespot daemon starting... May 17 18:35:43 primo go-librespot[5124]: time="2026-05-17T18:35:43+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:43 primo go-librespot[5124]: time="2026-05-17T18:35:43+01:00" level=debug msg="app state loaded" May 17 18:35:43 primo go-librespot[5124]: time="2026-05-17T18:35:43+01:00" level=debug msg="stored credentials not found" May 17 18:35:43 primo go-librespot[5124]: time="2026-05-17T18:35:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:43 primo go-librespot[5124]: time="2026-05-17T18:35:43+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:43+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:43 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:43 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:44 primo volumio[3561]: info: FusionDsp - Clipping Monitor started May 17 18:35:44 primo kernel: input: Z Fold7 de Gabriel (AVRCP) as /devices/virtual/input/input7 May 17 18:35:44 primo bluealsa[3440]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_8F_68_4B_2E_E5/avrcp/player0, ...) May 17 18:35:45 primo volumio[3561]: ------------------------------------ BT MESSAGE: [_watchMediaPlayer] Binding player for path: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5/avrcp/player0 mac: 70:8F:68:4B:2E:E5 May 17 18:35:45 primo volumio[3561]: ------------------------------------ BT MESSAGE: activePlayer bound: /org/bluez/hci0/dev_70_8F_68_4B_2E_E5/avrcp/player0 May 17 18:35:45 primo volumio[3561]: ------------------------------------ BT MESSAGE: Seek received post-resume, pushing metadata May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:45 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.028+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=0 volume=61 May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.029+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:45 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:45 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:45 primo systemd[1]: Stopping triggerhappy.service - triggerhappy global hotkey daemon... May 17 18:35:45 primo volumio[3561]: ------------------------------------ BT MESSAGE: Debounce: dropped pending playback=false for 70:8F:68:4B:2E:E5 (true arrived within window) May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:45 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:45 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.226+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136461 volume=61 May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.226+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.228+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136461 volume=61 May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.228+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:45 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:45 primo systemd[1]: triggerhappy.service: Deactivated successfully. May 17 18:35:45 primo systemd[1]: Stopped triggerhappy.service - triggerhappy global hotkey daemon. May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:45 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:45 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::servicePushState May 17 18:35:45 primo volumio[3561]: info: CoreStateMachine::pushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 18:35:45 primo systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioPushState May 17 18:35:45 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output update for this device May 17 18:35:45 primo volumio[3561]: info: MRS: Pushing multiroomSync output May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.282+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136461 volume=61 May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.282+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.284+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136461 volume=61 May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.284+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.286+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136461 volume=61 May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.288+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" state=STATUS_PLAYING positionMs=136461 volume=61 May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.295+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:45 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:45.296+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:45 primo thd[5134]: Unable to parse trigger line: May 17 18:35:45 primo thd[5134]: Unable to parse trigger line: May 17 18:35:45 primo thd[5134]: Unable to parse trigger line: May 17 18:35:45 primo systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. May 17 18:35:45 primo systemd-logind[2909]: Watching system buttons on /dev/input/event5 (Z Fold7 de Gabriel (AVRCP)) May 17 18:35:45 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:45 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:45 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:45 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:45 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:45 primo volumio[3561]: info: Signalling Playback active due to playback status change May 17 18:35:45 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:45 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:45 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:45 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:45 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:45 primo volumio[3561]: info: Updating RAAT Signal Path May 17 18:35:45 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:45 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:46 primo kernel: asoc-aml-card auge_sound: tdm playback stop May 17 18:35:46 primo kernel: spdif_a is set to disable May 17 18:35:46 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:46.703+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 May 17 18:35:46 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:46.704+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%02 @ 0x18c33e0" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" May 17 18:35:46 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:46.704+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title= May 17 18:35:46 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 45. May 17 18:35:46 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:46 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:46 primo go-librespot[5152]: go-librespot daemon starting... May 17 18:35:46 primo go-librespot[5153]: time="2026-05-17T18:35:46+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:46 primo go-librespot[5153]: time="2026-05-17T18:35:46+01:00" level=debug msg="app state loaded" May 17 18:35:46 primo go-librespot[5153]: time="2026-05-17T18:35:46+01:00" level=debug msg="stored credentials not found" May 17 18:35:46 primo go-librespot[5153]: time="2026-05-17T18:35:46+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:47 primo go-librespot[5153]: time="2026-05-17T18:35:47+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:47+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:47 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:47 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:48 primo volumio[3561]: info: Initializing connection to go-librespot Websocket May 17 18:35:48 primo volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 17 18:35:48 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:48.911+01:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.112:35826 May 17 18:35:48 primo volumio[3561]: verbose: New Socket.io Connection to 192.168.1.111 from 192.168.1.112 UA: Mozilla/5.0 (Linux; Android 16; SM-F966U1 Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.199 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::volumioGetVisibleSources May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 17 18:35:48 primo volumio[3561]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom May 17 18:35:48 primo volumio[3561]: info: Received Get System Info May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 17 18:35:48 primo volumio[3561]: info: Discovery: Getting this device information May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:48 primo volumio[3561]: info: Listing playlists May 17 18:35:48 primo volumio[3561]: info: CoreCommandRouter::volumioGetQueue May 17 18:35:48 primo volumio[3561]: info: CoreStateMachine::getQueue May 17 18:35:48 primo volumio[3561]: info: CorePlayQueue::getQueue May 17 18:35:48 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:48.997+01:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.133+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=135.977167ms error="Head \"https://radio-directory.firebaseapp.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-07-20T15:01:16Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.148+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=http://pushupdates.volumio.org duration=146.180375ms May 17 18:35:49 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 17 18:35:49 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 17 18:35:49 primo volumio[3561]: info: Discovery: Getting this device information May 17 18:35:49 primo volumio[3561]: info: CoreCommandRouter::volumioGetState May 17 18:35:49 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 17 18:35:49 primo volumio[3561]: info: CoreCommandRouter::getUIConfigOnPlugin May 17 18:35:49 primo volumio[3561]: info: CoreCommandRouter::getUIConfigOnPlugin May 17 18:35:49 primo volumio[3561]: info: CoreCommandRouter::getUIConfigOnPlugin May 17 18:35:49 primo volumio[3561]: info: CoreCommandRouter::getUIConfigOnPlugin May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.264+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title= May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.264+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id= title= May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.335+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://google.com duration=337.630083ms error="Head \"https://google.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-08-10T08:37:35Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.382+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://www.googleapis.com duration=382.002792ms error="Head \"https://www.googleapis.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-08-10T08:39:04Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.396+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://functions.volumio.cloud duration=394.161709ms error="Head \"https://functions.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-07-02T14:14:43Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.405+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://functions.volumio.cloud duration=406.279708ms error="Head \"https://functions.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-07-02T14:14:43Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.405+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://securetoken.googleapis.com duration=403.931708ms error="Head \"https://securetoken.googleapis.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-08-10T08:39:04Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.439+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://database.volumio.cloud duration=437.595541ms error="Head \"https://database.volumio.cloud\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-07-02T14:14:43Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.446+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=448.085959ms error="Head \"https://myvolumio.firebaseio.com\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-07-06T15:01:47Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.455+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=456.778667ms error="Head \"https://oauth-performer.dfs.volumio.org\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-07-08T11:28:45Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.473+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=475.13525ms error="Head \"https://browsing-performer.dfs.volumio.org\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:49+01:00 is before 2026-07-24T11:26:04Z" May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.555+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title= May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.555+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id= title= May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.674+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title= May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.675+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id= title= May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.949+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=http://cddb.volumio.org duration=949.044459ms May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.975+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title= May 17 18:35:49 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:49.975+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id= title= May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.095+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.096+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id= title="A lista" May 17 18:35:50 primo volumio[3561]: verbose: New Socket.io Connection to 192.168.1.111:3000 from 192.168.1.112 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 10 May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.121+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" latency=-2494h58m0.361110062s timeout=10s endpoint=http://plugins.volumio.org duration=1.119761792s May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.274+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.275+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id= title="A lista" May 17 18:35:50 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 46. May 17 18:35:50 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:50 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.396+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.396+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo go-librespot[5160]: go-librespot daemon starting... May 17 18:35:50 primo go-librespot[5161]: time="2026-05-17T18:35:50+01:00" level=info msg="running go-librespot 0.7.1" May 17 18:35:50 primo go-librespot[5161]: time="2026-05-17T18:35:50+01:00" level=debug msg="app state loaded" May 17 18:35:50 primo go-librespot[5161]: time="2026-05-17T18:35:50+01:00" level=debug msg="stored credentials not found" May 17 18:35:50 primo go-librespot[5161]: time="2026-05-17T18:35:50+01:00" level=info msg="api server listening on 127.0.0.1:9879" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.515+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.515+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.637+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.638+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo volumio[3561]: An internal error occurred while serving an albumart. Details: NotFoundError: Not Found May 17 18:35:50 primo volumio[3561]: at createHttpError (/volumio/node_modules/send/index.js:979:12) May 17 18:35:50 primo volumio[3561]: at SendStream.error (/volumio/node_modules/send/index.js:270:31) May 17 18:35:50 primo volumio[3561]: at SendStream.pipe (/volumio/node_modules/send/index.js:580:14) May 17 18:35:50 primo volumio[3561]: at sendfile (/volumio/node_modules/express/lib/response.js:1139:8) May 17 18:35:50 primo volumio[3561]: at ServerResponse.sendFile (/volumio/node_modules/express/lib/response.js:450:3) May 17 18:35:50 primo volumio[3561]: at Promise._failFn (/volumio/app/plugins/miscellanea/albumart/albumart.js:449:13) May 17 18:35:50 primo volumio[3561]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) May 17 18:35:50 primo volumio[3561]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.755+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.755+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo go-librespot[5161]: time="2026-05-17T18:35:50+01:00" level=fatal msg="failed running zeroconf" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2026-05-17T18:35:50+01:00 is before 2026-07-09T00:00:00Z" May 17 18:35:50 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 17 18:35:50 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.874+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.875+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id=spotify:track:6cGcgAvBwT6EFukPAuRTBj title="Namora Com O Telefone" May 17 18:35:50 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 17 18:35:50 primo volumio[3561]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.995+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:50 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:50.995+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id= title="A lista" May 17 18:35:51 primo volumio[3561]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 17 18:35:51 primo volumio[3561]: Error: certificate is not yet valid May 17 18:35:51 primo volumio[3561]: at TLSSocket.onConnectSecure (node:_tls_wrap:1627:34) May 17 18:35:51 primo volumio[3561]: at TLSSocket.emit (node:events:514:28) May 17 18:35:51 primo volumio[3561]: at TLSSocket._finishInit (node:_tls_wrap:1038:8) May 17 18:35:51 primo volumio[3561]: at ssl.onhandshakedone (node:_tls_wrap:824:12) { May 17 18:35:51 primo volumio[3561]: code: 'CERT_NOT_YET_VALID' May 17 18:35:51 primo volumio[3561]: } May 17 18:35:51 primo volumio[3561]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 17 18:35:51 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:51.115+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.115:34222 @ 0x18c3650" id= title="A lista" May 17 18:35:51 primo volumio5-onboarding[3855]: time=2026-05-17T18:35:51.115+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.112:35826,00:00:00:00:00:00%02 @ 0x1d2a570" id= title="A lista" May 17 18:35:51 primo sudo[5177]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-17 18:34' May 17 18:35:51 primo sudo[5177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="9ccd1247f8cab3c5d64c23a96d243f6bfa34d032" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="9938d7179e3b7c4e41f3e2d60c255985cff08fee" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun May 17 17:32:08 UTC 2026" VOLUMIO_VERSION="4.158" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="43d420a3aa41c50690ebfe378df38e2b"