Aug 30 21:50:00 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:00 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:01 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 69. Aug 30 21:50:01 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:01 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:01 volumiosalon go-librespot[3034]: go-librespot daemon starting... Aug 30 21:50:01 volumiosalon go-librespot[3035]: time="2026-08-30T21:50:01+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:01 volumiosalon go-librespot[3035]: time="2026-08-30T21:50:01+02:00" level=debug msg="app state loaded" Aug 30 21:50:01 volumiosalon go-librespot[3035]: time="2026-08-30T21:50:01+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:01 volumiosalon go-librespot[3035]: time="2026-08-30T21:50:01+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Aug 30 21:50:01 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:01 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:03 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:03 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:04 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 70. Aug 30 21:50:04 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:04 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:04 volumiosalon go-librespot[3045]: go-librespot daemon starting... Aug 30 21:50:04 volumiosalon go-librespot[3046]: time="2026-08-30T21:50:04+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:04 volumiosalon go-librespot[3046]: time="2026-08-30T21:50:04+02:00" level=debug msg="app state loaded" Aug 30 21:50:04 volumiosalon go-librespot[3046]: time="2026-08-30T21:50:04+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:04 volumiosalon go-librespot[3046]: time="2026-08-30T21:50:04+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Aug 30 21:50:04 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:04 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:06 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:06 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:07 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71. Aug 30 21:50:07 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:07 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:07 volumiosalon go-librespot[3057]: go-librespot daemon starting... Aug 30 21:50:08 volumiosalon go-librespot[3058]: time="2026-08-30T21:50:08+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:08 volumiosalon go-librespot[3058]: time="2026-08-30T21:50:08+02:00" level=debug msg="app state loaded" Aug 30 21:50:08 volumiosalon go-librespot[3058]: time="2026-08-30T21:50:08+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:08 volumiosalon go-librespot[3058]: time="2026-08-30T21:50:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Aug 30 21:50:08 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:08 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:08 volumiosalon dhcpcd[915]: eth0: carrier acquired Aug 30 21:50:08 volumiosalon kernel: r8169 0000:01:00.0 eth0: Link is Up - 1Gbps/Full - flow control rx/tx Aug 30 21:50:08 volumiosalon dhcpcd[915]: eth0: IAID fa:d4:1c:84 Aug 30 21:50:08 volumiosalon dhcpcd[915]: eth0: soliciting a DHCP lease Aug 30 21:50:08 volumiosalon ifplugd(eth0)[988]: Link beat detected. Aug 30 21:50:08 volumiosalon volumio[1026]: info: Received Get System Info Aug 30 21:50:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 21:50:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 21:50:08 volumiosalon volumio[1026]: info: Discovery: Getting this device information Aug 30 21:50:08 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:50:08 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 21:50:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 21:50:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 21:50:08 volumiosalon ifplugd(eth0)[988]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Aug 30 21:50:08 volumiosalon ifplugd(eth0)[988]: client: command failed: No such device (-19) Aug 30 21:50:08 volumiosalon ifplugd(eth0)[988]: client: sending commands to dhcpcd process Aug 30 21:50:08 volumiosalon dhcpcd[915]: control_free: No such file or directory Aug 30 21:50:08 volumiosalon dhcpcd[915]: ps_ctl_dispatch: cannot handle another client Aug 30 21:50:08 volumiosalon dhcpcd[915]: eth0: soliciting an IPv6 router Aug 30 21:50:09 volumiosalon ifplugd(eth0)[988]: Program executed successfully. Aug 30 21:50:09 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:50:09.495+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 30 21:50:09 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:09 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:11 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72. Aug 30 21:50:11 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:11 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:11 volumiosalon go-librespot[3134]: go-librespot daemon starting... Aug 30 21:50:11 volumiosalon go-librespot[3135]: time="2026-08-30T21:50:11+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:11 volumiosalon go-librespot[3135]: time="2026-08-30T21:50:11+02:00" level=debug msg="app state loaded" Aug 30 21:50:11 volumiosalon go-librespot[3135]: time="2026-08-30T21:50:11+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:11 volumiosalon go-librespot[3135]: time="2026-08-30T21:50:11+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Aug 30 21:50:11 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:11 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:11 volumiosalon dhcpcd[915]: eth0: offered 10.0.1.53 from 10.0.1.1 Aug 30 21:50:11 volumiosalon dhcpcd[915]: eth0: probing address 10.0.1.53/24 Aug 30 21:50:12 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:12 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:14 volumiosalon systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5. Aug 30 21:50:14 volumiosalon systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 21:50:14 volumiosalon systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 21:50:14 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 73. Aug 30 21:50:14 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:14 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:14 volumiosalon go-librespot[3155]: go-librespot daemon starting... Aug 30 21:50:14 volumiosalon go-librespot[3156]: time="2026-08-30T21:50:14+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:14 volumiosalon go-librespot[3156]: time="2026-08-30T21:50:14+02:00" level=debug msg="app state loaded" Aug 30 21:50:14 volumiosalon go-librespot[3156]: time="2026-08-30T21:50:14+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:14 volumiosalon go-librespot[3156]: time="2026-08-30T21:50:14+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Aug 30 21:50:14 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:14 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:15 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:15 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:16 volumiosalon dhcpcd[915]: eth0: leased 10.0.1.53 for 86400 seconds Aug 30 21:50:16 volumiosalon dhcpcd[915]: eth0: adding route to 10.0.1.0/24 Aug 30 21:50:16 volumiosalon avahi-daemon[773]: Joining mDNS multicast group on interface eth0.IPv4 with address 10.0.1.53. Aug 30 21:50:16 volumiosalon avahi-daemon[773]: New relevant interface eth0.IPv4 for mDNS. Aug 30 21:50:16 volumiosalon avahi-daemon[773]: Registering new address record for 10.0.1.53 on eth0.IPv4. Aug 30 21:50:16 volumiosalon dhcpcd[915]: eth0: adding default route via 10.0.1.1 Aug 30 21:50:16 volumiosalon systemd[1]: welcome.service: Deactivated successfully. Aug 30 21:50:16 volumiosalon systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 30 21:50:16 volumiosalon systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 30 21:50:16 volumiosalon systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 30 21:50:16 volumiosalon welcome[3180]: Resolved ip:[1] 10.0.1.53 Aug 30 21:50:16 volumiosalon systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 30 21:50:16 volumiosalon systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 30 21:50:17 volumiosalon volumio[1026]: info: Received Get System Info Aug 30 21:50:17 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 21:50:17 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 21:50:17 volumiosalon volumio[1026]: info: Discovery: Getting this device information Aug 30 21:50:17 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:50:17 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:17 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 21:50:17 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 21:50:17 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 21:50:17 volumiosalon volumio[1026]: info: Discovery: this is already registered, 9f9c5a06-7912-4283-a715-7cf06fbaadbd Aug 30 21:50:17 volumiosalon volumio[1026]: info: Discovery: Found device VolumioSalon Aug 30 21:50:17 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:50:17 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:17 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 74. Aug 30 21:50:17 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:17 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:17 volumiosalon go-librespot[3193]: go-librespot daemon starting... Aug 30 21:50:17 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:17+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:17 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:17+02:00" level=debug msg="app state loaded" Aug 30 21:50:17 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:17+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=info msg="zeroconf server listening on port 34847" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 21:50:18 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:50:18.127+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 30 21:50:18 volumiosalon volumio[1026]: info: Volumio Network Manager: Network status updated: 1 Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=debug msg="obtained new client token: AAFIV+rpPZ0wINr8K/FPEYLRU0i02xOQhG4zEDTQwIXrtO1KJyk76ff9yWYQBI7Sx6EvI8VbfSddQ9ukkMBG0sH2z3o7+N3IXi5Gy/RnTjJtl4dEjhU9ShlqSpLIE1l7zLxcV1pFY408oZqUkl7aE02OFNDNypSfbFMqXK+JdFN/dMRdufiWmYm8qbRDkCmzHxNRunnQgMLhhVntixskFUindxT6vFywg1/ZvCcEt1Ih+RmMwIKR" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=debug msg="completed keyexchange" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=debug msg="completed challenge" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=info msg="authenticated AP" username="vo***kh" Aug 30 21:50:18 volumiosalon go-librespot[3194]: time="2026-08-30T21:50:18+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 21:50:18 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:18 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:18 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:18 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:18 volumiosalon ntpd[970]: IO: Listen normally on 3 eth0 10.0.1.53:123 Aug 30 21:50:18 volumiosalon ntpd[970]: IO: new interface(s) found: waking up resolver Aug 30 21:50:18 volumiosalon ntpd[970]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 30 21:50:18 volumiosalon ntpd[970]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Aug 30 21:50:18 volumiosalon ntpd[970]: DNS: Pool taking: 162.159.200.1 Aug 30 21:50:18 volumiosalon ntpd[970]: DNS: Pool taking: 78.9.233.189 Aug 30 21:50:18 volumiosalon ntpd[970]: DNS: Pool taking: 91.212.242.21 Aug 30 21:50:18 volumiosalon ntpd[970]: DNS: Pool taking: 89.161.47.133 Aug 30 21:50:18 volumiosalon ntpd[970]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: Pool taking: 193.25.222.136 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: Pool taking: 94.154.96.7 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: Pool taking: 51.68.141.5 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: Pool taking: 89.161.47.139 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: Pool taking: 2a03:7580:1:217::10 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: Pool taking: 2001:41d0:601:1100::45d2 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: Pool taking: 2a12:bec4:1da0:3e::123 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: Pool taking: 2a12:bec4:1821:5f1::123 Aug 30 21:50:19 volumiosalon ntpd[970]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Aug 30 21:50:20 volumiosalon ntpd[970]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 30 21:50:20 volumiosalon ntpd[970]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Aug 30 21:50:20 volumiosalon ntpd[970]: DNS: Pool taking: 194.146.251.101 Aug 30 21:50:20 volumiosalon ntpd[970]: DNS: Pool skipping: 51.68.141.5 Aug 30 21:50:20 volumiosalon ntpd[970]: DNS: Pool taking: 109.206.205.233 Aug 30 21:50:20 volumiosalon ntpd[970]: DNS: Pool taking: 162.159.200.123 Aug 30 21:50:20 volumiosalon ntpd[970]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 30 21:50:21 volumiosalon volumio[1026]: info: Adding plugin bluetooth to MyMusic Plugins Aug 30 21:50:21 volumiosalon volumio[1026]: info: Adding plugin multiroom to MyMusic Plugins Aug 30 21:50:21 volumiosalon volumio[1026]: info: Adding plugin metavolumio to MyMusic Plugins Aug 30 21:50:21 volumiosalon volumio[1026]: info: Adding plugin cd_controller to MyMusic Plugins Aug 30 21:50:21 volumiosalon volumio[1026]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 30 21:50:21 volumiosalon volumio[1026]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 30 21:50:21 volumiosalon volumio[1026]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 30 21:50:21 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 30 21:50:21 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 75. Aug 30 21:50:21 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:21 volumiosalon ntpd[970]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 30 21:50:21 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:21 volumiosalon ntpd[970]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Aug 30 21:50:21 volumiosalon ntpd[970]: DNS: Pool skipping: 94.154.96.7 Aug 30 21:50:21 volumiosalon ntpd[970]: DNS: Pool skipping: 193.25.222.136 Aug 30 21:50:21 volumiosalon ntpd[970]: DNS: Pool taking: 213.222.217.11 Aug 30 21:50:21 volumiosalon ntpd[970]: DNS: Pool taking: 212.127.78.21 Aug 30 21:50:21 volumiosalon ntpd[970]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Aug 30 21:50:21 volumiosalon go-librespot[3236]: go-librespot daemon starting... Aug 30 21:50:21 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:21+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:21 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:21+02:00" level=debug msg="app state loaded" Aug 30 21:50:21 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=info msg="zeroconf server listening on port 40299" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=debug msg="obtained new client token: AAGJf46aI0HAXoLRKejxkPfHAv3qewA+VSSfU1bRaJf8B4D4SGCQHgoXxsreOh2fgtR5gMs4MYYFbBKnAbPrgr3awy6a0cnfbhWuZuWshKMO5U/0urnOqOnF17u9c55jsxBNdt5/Z8+p6NLYvkK+NKTu+BpzJ1GjRYGrh9UDo92WAOVNi46vO1GQATgBfaJpAGMBOUARpVOHx4TeZrUZo2zdbdWkxbe5ckZgQ3hsghVHwalAAoKZ2k8=" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=debug msg="completed keyexchange" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=debug msg="completed challenge" Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=info msg="authenticated AP" username="vo***kh" Aug 30 21:50:22 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 30 21:50:22 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 30 21:50:22 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:22 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:22 volumiosalon volumio[1026]: info: Starting MyVolumio Remote Streaming Endpoints Aug 30 21:50:22 volumiosalon volumio[1026]: info: MyVolumio login type: Token Aug 30 21:50:22 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 30 21:50:22 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 30 21:50:22 volumiosalon go-librespot[3238]: time="2026-08-30T21:50:22+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 21:50:22 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:22 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:23 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 30 21:50:23 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 30 21:50:23 volumiosalon volumio[1026]: info: Streaming services startup Aug 30 21:50:23 volumiosalon volumio[1026]: info: Starting Streaming Daemon Aug 30 21:50:23 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 30 21:50:23 volumiosalon sudo[3248]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 30 21:50:23 volumiosalon sudo[3248]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:23 volumiosalon sudo[3248]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:23 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:23 volumiosalon volumio[1026]: error: Cannot start Volumio Streaming Daemon Aug 30 21:50:23 volumiosalon volumio[1026]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 30 21:50:23 volumiosalon volumio[1026]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 30 21:50:23 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:24 volumiosalon volumio[1026]: error: MyVolumio Custom Token format not valid, refreshing it Aug 30 21:50:50 volumiosalon ntpd[970]: CLOCK: time stepped by 26.069371 Aug 30 21:50:50 volumiosalon ntpd[970]: INIT: MRU 10922 entries, 13 hash bits, 65536 bytes Aug 30 21:50:50 volumiosalon volumio[1026]: info: MyVolumio login type: Token Aug 30 21:50:51 volumiosalon volumio[1026]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 30 21:50:51 volumiosalon volumio[1026]: info: MyVolumio token set successfully Aug 30 21:50:51 volumiosalon volumio[1026]: info: MYVOLUMIO: Adding device Aug 30 21:50:51 volumiosalon volumio[1026]: info: MYVOLUMIO: Evaluating Server Aug 30 21:50:51 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 76. Aug 30 21:50:51 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:51 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:51 volumiosalon go-librespot[3259]: go-librespot daemon starting... Aug 30 21:50:51 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:51+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:51 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:51+02:00" level=debug msg="app state loaded" Aug 30 21:50:51 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:51+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=info msg="zeroconf server listening on port 41925" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 21:50:52 volumiosalon volumio[1026]: info: MyVolumio Plan changed: virtuoso Aug 30 21:50:52 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Subscribed plan changed to virtuoso Aug 30 21:50:52 volumiosalon volumio[1026]: info: Removing browser output: myVolumio user plan is not superstar Aug 30 21:50:52 volumiosalon volumio[1026]: info: Removing audio output: Aug 30 21:50:52 volumiosalon volumio[1026]: info: MYVOLUMIO: Adding device Aug 30 21:50:52 volumiosalon volumio[1026]: info: MYVOLUMIO: Evaluating Server Aug 30 21:50:52 volumiosalon volumio[1026]: info: Remote config written successfully Aug 30 21:50:52 volumiosalon volumio[1026]: info: Starting Tunnel 1 Aug 30 21:50:52 volumiosalon volumio[1026]: info: Starting Tunnel Connection Checker Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=debug msg="obtained new client token: AAFEizu8R+vnVd7/7JvWjIca0B61ISVu84sa5fpafO14WSW9yQW6rnYc4eIDkRBD7Cj6YZ2Dhfp1+j89b5pzxyMG6eKDIEUcAL5iYweVTuQG9EUh3fguBbuUDXfoY09B/3OiVn9CoNrcveit56naosUElfs0xMK+1WfwWzmvkEn8FNaD4WDss1Z5+S8VZrBGoZPfr0mMOc/luKIZSgYt+PAnSUX9wGSsV8aw0lgDDJkcOOkc9hJj" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=debug msg="completed keyexchange" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=debug msg="completed challenge" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=info msg="authenticated AP" username="vo***kh" Aug 30 21:50:52 volumiosalon go-librespot[3260]: time="2026-08-30T21:50:52+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 21:50:52 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:52 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:52 volumiosalon volumio[1026]: info: MYVolumio Device enabled Aug 30 21:50:52 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Aug 30 21:50:52 volumiosalon volumio[1026]: info: MyVolumio status changed Aug 30 21:50:52 volumiosalon volumio[1026]: info: Streaming services startup Aug 30 21:50:52 volumiosalon volumio[1026]: info: Starting Streaming Daemon Aug 30 21:50:52 volumiosalon sudo[3306]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 30 21:50:52 volumiosalon volumio[1026]: info: Setting Geolocation for MyVolumio to eu6 Aug 30 21:50:52 volumiosalon sudo[3306]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:52 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:52 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:52 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:52 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Aug 30 21:50:52 volumiosalon volumio[1026]: error: [MyVolumio PluginManager] Cache data is invalid! Aug 30 21:50:52 volumiosalon sudo[3306]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:52 volumiosalon volumio[1026]: error: Cannot start Volumio Streaming Daemon Aug 30 21:50:52 volumiosalon volumio[1026]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 30 21:50:52 volumiosalon volumio[1026]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 30 21:50:52 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:52 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:52 volumiosalon volumio[1026]: info: Setting Geolocation for MyVolumio to eu11 Aug 30 21:50:52 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:52 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:52 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin bluetooth Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin bluetooth Aug 30 21:50:53 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Aug 30 21:50:53 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: [FUNC] onStart Aug 30 21:50:53 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Aug 30 21:50:53 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Aug 30 21:50:53 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Aug 30 21:50:53 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Aug 30 21:50:53 volumiosalon volumio[1026]: info: Preparing CD Folders Aug 30 21:50:53 volumiosalon volumio[1026]: info: Adding CD REST API Endpoints Aug 30 21:50:53 volumiosalon volumio[1026]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Aug 30 21:50:53 volumiosalon volumio[1026]: info: Starting UDEV Watcher for CD Aug 30 21:50:53 volumiosalon volumio[1026]: info: Detecting CD presence with UDEV Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Aug 30 21:50:53 volumiosalon sudo[3313]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /dev/sr0 Aug 30 21:50:53 volumiosalon sudo[3313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:53 volumiosalon sudo[3313]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:53 volumiosalon sudo[3317]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /dev/sr1 Aug 30 21:50:53 volumiosalon sudo[3317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:53 volumiosalon sudo[3317]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:53 volumiosalon volumio[1026]: /bin/chmod: cannot access '/dev/sr1': No such file or directory Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 21:50:53 volumiosalon volumio[1026]: info: [1788119453533] CoreMusicLibrary::Adding element Audio CD Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 21:50:53 volumiosalon volumio[1026]: Cannot find translation for source RADIO 357 Aug 30 21:50:53 volumiosalon volumio[1026]: Cannot find translation for source Radio Browser Aug 30 21:50:53 volumiosalon volumio[1026]: Cannot find translation for source Audio CD Aug 30 21:50:53 volumiosalon volumio[1026]: info: [cd-plugin] Set CD speed to 1X Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Aug 30 21:50:53 volumiosalon volumio[1026]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Aug 30 21:50:53 volumiosalon volumio[1026]: info: Adding TIDAL REST API Endpoints Aug 30 21:50:53 volumiosalon volumio[1026]: info: Stopping AccessToken refresher cron for QOBUZ Aug 30 21:50:53 volumiosalon sudo[3326]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 30 21:50:53 volumiosalon sudo[3326]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:53 volumiosalon volumio[1026]: info: AccessToken refresher cron started for QOBUZ Aug 30 21:50:53 volumiosalon volumio[1026]: info: Adding QOBUZ REST API Endpoints Aug 30 21:50:53 volumiosalon sudo[3326]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:53 volumiosalon volumio[1026]: info: Updating MyVolumio device info Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Aug 30 21:50:53 volumiosalon volumio[1026]: info: Successfully Added MyVolumio device Aug 30 21:50:53 volumiosalon volumio[1026]: info: Successfully Added MyVolumio device Aug 30 21:50:53 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: Failed to power on adapter: Aug 30 21:50:53 volumiosalon sudo[3344]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Aug 30 21:50:53 volumiosalon sudo[3344]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:53 volumiosalon volumio[1026]: info: Updating MyVolumio device info Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:53 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:50:53 volumiosalon systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 21:50:54 volumiosalon sudo[3344]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:54 volumiosalon volumiobt[3366]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 21:50:54 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Aug 30 21:50:54 volumiosalon volumio[1026]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Aug 30 21:50:54 volumiosalon sudo[3368]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 21:50:54 volumiosalon sudo[3368]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:54 volumiosalon sudo[3368]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:54 volumiosalon volumio[1026]: info: Successfully Updated MyVolumio device Aug 30 21:50:54 volumiosalon sudo[3376]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 21:50:54 volumiosalon sudo[3376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:54 volumiosalon sudo[3376]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:54 volumiosalon volumiobt[3381]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 21:50:54 volumiosalon volumiobt[3391]: No default controller available Aug 30 21:50:54 volumiosalon volumio[1026]: info: Successfully Updated MyVolumio device Aug 30 21:50:55 volumiosalon volumiobt[3423]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 30 21:50:55 volumiosalon volumiobt[3424]: [83B blob data] Aug 30 21:50:55 volumiosalon volumiobt[3424]: No default controller available Aug 30 21:50:55 volumiosalon volumiobt[3424]: [bluetoothctl]> pairable on Aug 30 21:50:55 volumiosalon volumiobt[3424]: No default controller available Aug 30 21:50:55 volumiosalon volumiobt[3424]: [bluetoothctl]> Aug 30 21:50:55 volumiosalon volumiobt[3425]: INFO [BTSTART] Registering Bluetooth agent... Aug 30 21:50:55 volumiosalon volumiobt[3427]: No agent is registered Aug 30 21:50:55 volumiosalon volumiobt[3428]: INFO [BTSTART] Agent registered successfully. Aug 30 21:50:55 volumiosalon volumiobt[3429]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 30 21:50:55 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:55 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:55 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 77. Aug 30 21:50:55 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:55 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:55 volumiosalon go-librespot[3432]: go-librespot daemon starting... Aug 30 21:50:55 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:55+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:55 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:55+02:00" level=debug msg="app state loaded" Aug 30 21:50:55 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:55+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=info msg="zeroconf server listening on port 34439" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=debug msg="obtained new client token: AAEVA6IlXJTtc/ES8SgMICmhvYVVxsv2PxifCFwj+D0iQNzb/3NNy8035EQRHa1R8PgzbcRcS4GvqTE08iokcU4xDEtg39ZzGx/YuJ+AubcRS5ipvK/BVKP3obqeZLAo5S0+9HvjfVI2PVtRcKDaJrkIH2szrv+/H9wT9P9MKCclB4CMCC1RNAOEAc6HO8/6dPWAmHrc6aTa/Hzfsw5/IXdt+G2nkmTQg2PdeL2FogSGCgt45dB+" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=debug msg="completed keyexchange" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=debug msg="completed challenge" Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=info msg="authenticated AP" username="vo***kh" Aug 30 21:50:56 volumiosalon volumiobt[3430]: 2026-08-30 21:50:56 a2dp-agent [INFO] Connecting to system D-Bus Aug 30 21:50:56 volumiosalon volumiobt[3430]: 2026-08-30 21:50:56 a2dp-agent [INFO] Connected to system D-Bus Aug 30 21:50:56 volumiosalon volumiobt[3430]: 2026-08-30 21:50:56 a2dp-agent [ERROR] No Bluetooth adapter found: Bluetooth adapter not found Aug 30 21:50:56 volumiosalon volumiobt[3430]: 2026-08-30 21:50:56 a2dp-agent [ERROR] Agent crashed: Bluetooth adapter not found Aug 30 21:50:56 volumiosalon volumiobt[3430]: Traceback (most recent call last): Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:50:56 volumiosalon volumiobt[3430]: asyncio.run(_run()) Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:50:56 volumiosalon volumiobt[3430]: return runner.run(main) Aug 30 21:50:56 volumiosalon volumiobt[3430]: ^^^^^^^^^^^^^^^^ Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:50:56 volumiosalon volumiobt[3430]: return self._loop.run_until_complete(task) Aug 30 21:50:56 volumiosalon volumiobt[3430]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:50:56 volumiosalon volumiobt[3430]: return future.result() Aug 30 21:50:56 volumiosalon volumiobt[3430]: ^^^^^^^^^^^^^^^ Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:50:56 volumiosalon volumiobt[3430]: adapter_path = await find_adapter(bus) Aug 30 21:50:56 volumiosalon volumiobt[3430]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:50:56 volumiosalon volumiobt[3430]: raise Exception("Bluetooth adapter not found") Aug 30 21:50:56 volumiosalon volumiobt[3430]: Exception: Bluetooth adapter not found Aug 30 21:50:56 volumiosalon volumiobt[3430]: Traceback (most recent call last): Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/bin/bt/a2dp-agent", line 234, in Aug 30 21:50:56 volumiosalon volumiobt[3430]: main() Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:50:56 volumiosalon volumiobt[3430]: asyncio.run(_run()) Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:50:56 volumiosalon volumiobt[3430]: return runner.run(main) Aug 30 21:50:56 volumiosalon volumiobt[3430]: ^^^^^^^^^^^^^^^^ Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:50:56 volumiosalon volumiobt[3430]: return self._loop.run_until_complete(task) Aug 30 21:50:56 volumiosalon volumiobt[3430]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:50:56 volumiosalon volumiobt[3430]: return future.result() Aug 30 21:50:56 volumiosalon volumiobt[3430]: ^^^^^^^^^^^^^^^ Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:50:56 volumiosalon volumiobt[3430]: adapter_path = await find_adapter(bus) Aug 30 21:50:56 volumiosalon volumiobt[3430]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:50:56 volumiosalon volumiobt[3430]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:50:56 volumiosalon volumiobt[3430]: raise Exception("Bluetooth adapter not found") Aug 30 21:50:56 volumiosalon volumiobt[3430]: Exception: Bluetooth adapter not found Aug 30 21:50:56 volumiosalon go-librespot[3433]: time="2026-08-30T21:50:56+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 21:50:56 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:56 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:50:56 volumiosalon systemd[1]: volumiobt.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:56 volumiosalon systemd[1]: volumiobt.service: Failed with result 'exit-code'. Aug 30 21:50:56 volumiosalon systemd[1]: volumiobt.service: Scheduled restart job, restart counter is at 1. Aug 30 21:50:56 volumiosalon systemd[1]: Stopped volumiobt.service - Volumio Bluetooth Module. Aug 30 21:50:56 volumiosalon volumio[1026]: info: TidalConnect service stoped! Aug 30 21:50:56 volumiosalon systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 21:50:56 volumiosalon volumiobt[3465]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 21:50:56 volumiosalon sudo[3468]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 21:50:56 volumiosalon sudo[3468]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:56 volumiosalon sudo[3468]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:56 volumiosalon sudo[3474]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 21:50:56 volumiosalon sudo[3474]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:56 volumiosalon volumio[1026]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 30 21:50:56 volumiosalon sudo[3474]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:56 volumiosalon volumio[1026]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 30 21:50:57 volumiosalon volumiobt[3476]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 21:50:57 volumiosalon volumiobt[3481]: No default controller available Aug 30 21:50:57 volumiosalon sudo[3480]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 30 21:50:57 volumiosalon sudo[3480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:57 volumiosalon systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Aug 30 21:50:57 volumiosalon sudo[3480]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:57 volumiosalon sudo[3493]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Aug 30 21:50:57 volumiosalon sudo[3493]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:57 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 30 21:50:57 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 30 21:50:57 volumiosalon systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Aug 30 21:50:57 volumiosalon sudo[3493]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:57 volumiosalon autossh[3496]: port set to 0, monitoring disabled Aug 30 21:50:57 volumiosalon autossh[3496]: starting ssh (count 1) Aug 30 21:50:57 volumiosalon autossh[3496]: ssh child pid is 3500 Aug 30 21:50:57 volumiosalon volumio[1026]: info: Executing endpoint tc_getconfig Aug 30 21:50:57 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Aug 30 21:50:57 volumiosalon vtcs[3485]: STARTING TidalConnect services, version: 1.6.1 Aug 30 21:50:57 volumiosalon volumio[1026]: info: Remote SSH Started Aug 30 21:50:57 volumiosalon vtcs[3485]: STARTED TidalConnect services. Aug 30 21:50:57 volumiosalon volumiossh-tunnel[3500]: Warning: Permanently added '[eu11.myvolumio.org]:2222' (ED25519) to the list of known hosts. Aug 30 21:50:58 volumiosalon volumiobt[3507]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 30 21:50:58 volumiosalon volumiobt[3508]: [83B blob data] Aug 30 21:50:58 volumiosalon volumiobt[3508]: No default controller available Aug 30 21:50:58 volumiosalon volumiobt[3508]: [bluetoothctl]> pairable on Aug 30 21:50:58 volumiosalon volumiobt[3508]: No default controller available Aug 30 21:50:58 volumiosalon volumiobt[3508]: [bluetoothctl]> Aug 30 21:50:58 volumiosalon volumiobt[3509]: INFO [BTSTART] Registering Bluetooth agent... Aug 30 21:50:58 volumiosalon volumio[1026]: info: Executing endpoint tc_connect Aug 30 21:50:58 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Aug 30 21:50:58 volumiosalon volumio[1026]: info: Connecting to TidalConnect Aug 30 21:50:58 volumiosalon volumiobt[3511]: No agent is registered Aug 30 21:50:58 volumiosalon volumio[1026]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Aug 30 21:50:58 volumiosalon volumiobt[3512]: INFO [BTSTART] Agent registered successfully. Aug 30 21:50:58 volumiosalon volumio[1026]: info: CoreCommandRouter::servicePushState Aug 30 21:50:58 volumiosalon volumio[1026]: info: CoreStateMachine::pushState Aug 30 21:50:58 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:58 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioPushState Aug 30 21:50:58 volumiosalon volumiobt[3517]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 30 21:50:58 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:58 volumiosalon volumio[1026]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received tidalconnect Aug 30 21:50:58 volumiosalon volumio[1026]: info: CoreCommandRouter::servicePushState Aug 30 21:50:58 volumiosalon volumio[1026]: info: CoreStateMachine::pushState Aug 30 21:50:58 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:58 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioPushState Aug 30 21:50:58 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:58 volumiosalon volumio[1026]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received tidalconnect Aug 30 21:50:58 volumiosalon volumio[1026]: info: [cd-plugin] Set CD speed to 1X Aug 30 21:50:58 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:50:58 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:58 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:50:58 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:50:59 volumiosalon volumiobt[3518]: 2026-08-30 21:50:59 a2dp-agent [INFO] Connecting to system D-Bus Aug 30 21:50:59 volumiosalon volumiobt[3518]: 2026-08-30 21:50:59 a2dp-agent [INFO] Connected to system D-Bus Aug 30 21:50:59 volumiosalon volumiobt[3518]: 2026-08-30 21:50:59 a2dp-agent [ERROR] No Bluetooth adapter found: Bluetooth adapter not found Aug 30 21:50:59 volumiosalon volumiobt[3518]: 2026-08-30 21:50:59 a2dp-agent [ERROR] Agent crashed: Bluetooth adapter not found Aug 30 21:50:59 volumiosalon volumiobt[3518]: Traceback (most recent call last): Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:50:59 volumiosalon volumiobt[3518]: asyncio.run(_run()) Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:50:59 volumiosalon volumiobt[3518]: return runner.run(main) Aug 30 21:50:59 volumiosalon volumiobt[3518]: ^^^^^^^^^^^^^^^^ Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:50:59 volumiosalon volumiobt[3518]: return self._loop.run_until_complete(task) Aug 30 21:50:59 volumiosalon volumiobt[3518]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:50:59 volumiosalon volumiobt[3518]: return future.result() Aug 30 21:50:59 volumiosalon volumiobt[3518]: ^^^^^^^^^^^^^^^ Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:50:59 volumiosalon volumiobt[3518]: adapter_path = await find_adapter(bus) Aug 30 21:50:59 volumiosalon volumiobt[3518]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:50:59 volumiosalon volumiobt[3518]: raise Exception("Bluetooth adapter not found") Aug 30 21:50:59 volumiosalon volumiobt[3518]: Exception: Bluetooth adapter not found Aug 30 21:50:59 volumiosalon volumiobt[3518]: Traceback (most recent call last): Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/bin/bt/a2dp-agent", line 234, in Aug 30 21:50:59 volumiosalon volumiobt[3518]: main() Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:50:59 volumiosalon volumiobt[3518]: asyncio.run(_run()) Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:50:59 volumiosalon volumiobt[3518]: return runner.run(main) Aug 30 21:50:59 volumiosalon volumiobt[3518]: ^^^^^^^^^^^^^^^^ Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:50:59 volumiosalon volumiobt[3518]: return self._loop.run_until_complete(task) Aug 30 21:50:59 volumiosalon volumiobt[3518]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:50:59 volumiosalon volumiobt[3518]: return future.result() Aug 30 21:50:59 volumiosalon volumiobt[3518]: ^^^^^^^^^^^^^^^ Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:50:59 volumiosalon volumiobt[3518]: adapter_path = await find_adapter(bus) Aug 30 21:50:59 volumiosalon volumiobt[3518]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:50:59 volumiosalon volumiobt[3518]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:50:59 volumiosalon volumiobt[3518]: raise Exception("Bluetooth adapter not found") Aug 30 21:50:59 volumiosalon volumiobt[3518]: Exception: Bluetooth adapter not found Aug 30 21:50:59 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:50:59.269+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=10.0.1.204:63996 Aug 30 21:50:59 volumiosalon volumio[1026]: verbose: New Socket.io Connection to 10.0.1.53:3000 from 10.0.1.204 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Aug 30 21:50:59 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 21:50:59 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 21:50:59 volumiosalon volumio[1026]: info: Discovery: Getting this device information Aug 30 21:50:59 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:50:59 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:50:59 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 21:50:59 volumiosalon systemd[1]: volumiobt.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:50:59 volumiosalon systemd[1]: volumiobt.service: Failed with result 'exit-code'. Aug 30 21:50:59 volumiosalon systemd[1]: volumiobt.service: Scheduled restart job, restart counter is at 2. Aug 30 21:50:59 volumiosalon systemd[1]: Stopped volumiobt.service - Volumio Bluetooth Module. Aug 30 21:50:59 volumiosalon systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 21:50:59 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 78. Aug 30 21:50:59 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:59 volumiosalon volumiobt[3529]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 21:50:59 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:50:59 volumiosalon go-librespot[3528]: go-librespot daemon starting... Aug 30 21:50:59 volumiosalon sudo[3530]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 21:50:59 volumiosalon sudo[3530]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:59 volumiosalon sudo[3530]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:59 volumiosalon go-librespot[3531]: time="2026-08-30T21:50:59+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:50:59 volumiosalon go-librespot[3531]: time="2026-08-30T21:50:59+02:00" level=debug msg="app state loaded" Aug 30 21:50:59 volumiosalon sudo[3537]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 21:50:59 volumiosalon sudo[3537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:50:59 volumiosalon sudo[3537]: pam_unix(sudo:session): session closed for user root Aug 30 21:50:59 volumiosalon go-librespot[3531]: time="2026-08-30T21:50:59+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:50:59 volumiosalon volumiobt[3542]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 21:50:59 volumiosalon volumiobt[3545]: No default controller available Aug 30 21:50:59 volumiosalon go-librespot[3531]: time="2026-08-30T21:50:59+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 21:50:59 volumiosalon go-librespot[3531]: time="2026-08-30T21:50:59+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 21:50:59 volumiosalon go-librespot[3531]: time="2026-08-30T21:50:59+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 21:50:59 volumiosalon go-librespot[3531]: time="2026-08-30T21:50:59+02:00" level=info msg="zeroconf server listening on port 42517" Aug 30 21:50:59 volumiosalon go-librespot[3531]: time="2026-08-30T21:50:59+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 21:51:00 volumiosalon go-librespot[3531]: time="2026-08-30T21:51:00+02:00" level=debug msg="obtained new client token: AAHh2TdScDfhX7No/IETqhq41ClceZkCVP6RxR6c9bpcvg/OAuyioHx+0YTmq1IDKXzsulDU0LuJron7hhh5E11PHs4LhTwvgJOtqr4XhGxU0of7zlpphuN3T0CWXuAhWnaXPT4Qhk4kEJwoIWXSgddpTN0OGd2kN/Ar/GagWEQd7s64O1EAe0n1CZlTQ9AEgsMygoM8ULFuFGwlZwiaqw95uzkisinkB3VXS/fxk4T5HhEKq1ws" Aug 30 21:51:00 volumiosalon go-librespot[3531]: time="2026-08-30T21:51:00+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 21:51:00 volumiosalon go-librespot[3531]: time="2026-08-30T21:51:00+02:00" level=debug msg="completed keyexchange" Aug 30 21:51:00 volumiosalon go-librespot[3531]: time="2026-08-30T21:51:00+02:00" level=debug msg="completed challenge" Aug 30 21:51:00 volumiosalon volumio[1026]: info: TidalConnect service started! Aug 30 21:51:00 volumiosalon go-librespot[3531]: time="2026-08-30T21:51:00+02:00" level=info msg="authenticated AP" username="vo***kh" Aug 30 21:51:00 volumiosalon go-librespot[3531]: time="2026-08-30T21:51:00+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 21:51:00 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:51:00 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:51:00 volumiosalon volumiobt[3614]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 30 21:51:00 volumiosalon volumiobt[3615]: [83B blob data] Aug 30 21:51:00 volumiosalon volumiobt[3615]: No default controller available Aug 30 21:51:00 volumiosalon volumiobt[3615]: [bluetoothctl]> pairable on Aug 30 21:51:00 volumiosalon volumiobt[3615]: No default controller available Aug 30 21:51:00 volumiosalon volumiobt[3615]: [113B blob data] Aug 30 21:51:00 volumiosalon volumiobt[3615]: [bluetoothctl]> Aug 30 21:51:00 volumiosalon volumiobt[3616]: INFO [BTSTART] Registering Bluetooth agent... Aug 30 21:51:00 volumiosalon volumiobt[3618]: No agent is registered Aug 30 21:51:00 volumiosalon volumiobt[3619]: INFO [BTSTART] Agent registered successfully. Aug 30 21:51:01 volumiosalon volumiobt[3620]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 30 21:51:01 volumiosalon volumiobt[3621]: 2026-08-30 21:51:01 a2dp-agent [INFO] Connecting to system D-Bus Aug 30 21:51:01 volumiosalon volumiobt[3621]: 2026-08-30 21:51:01 a2dp-agent [INFO] Connected to system D-Bus Aug 30 21:51:01 volumiosalon volumiobt[3621]: 2026-08-30 21:51:01 a2dp-agent [ERROR] No Bluetooth adapter found: Bluetooth adapter not found Aug 30 21:51:01 volumiosalon volumiobt[3621]: 2026-08-30 21:51:01 a2dp-agent [ERROR] Agent crashed: Bluetooth adapter not found Aug 30 21:51:01 volumiosalon volumiobt[3621]: Traceback (most recent call last): Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:01 volumiosalon volumiobt[3621]: asyncio.run(_run()) Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:01 volumiosalon volumiobt[3621]: return runner.run(main) Aug 30 21:51:01 volumiosalon volumiobt[3621]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:01 volumiosalon volumiobt[3621]: return self._loop.run_until_complete(task) Aug 30 21:51:01 volumiosalon volumiobt[3621]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:01 volumiosalon volumiobt[3621]: return future.result() Aug 30 21:51:01 volumiosalon volumiobt[3621]: ^^^^^^^^^^^^^^^ Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:01 volumiosalon volumiobt[3621]: adapter_path = await find_adapter(bus) Aug 30 21:51:01 volumiosalon volumiobt[3621]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:01 volumiosalon volumiobt[3621]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:01 volumiosalon volumiobt[3621]: Exception: Bluetooth adapter not found Aug 30 21:51:01 volumiosalon volumiobt[3621]: Traceback (most recent call last): Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/bin/bt/a2dp-agent", line 234, in Aug 30 21:51:01 volumiosalon volumiobt[3621]: main() Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:01 volumiosalon volumiobt[3621]: asyncio.run(_run()) Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:01 volumiosalon volumiobt[3621]: return runner.run(main) Aug 30 21:51:01 volumiosalon volumiobt[3621]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:01 volumiosalon volumiobt[3621]: return self._loop.run_until_complete(task) Aug 30 21:51:01 volumiosalon volumiobt[3621]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:01 volumiosalon volumiobt[3621]: return future.result() Aug 30 21:51:01 volumiosalon volumiobt[3621]: ^^^^^^^^^^^^^^^ Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:01 volumiosalon volumiobt[3621]: adapter_path = await find_adapter(bus) Aug 30 21:51:01 volumiosalon volumiobt[3621]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:01 volumiosalon volumiobt[3621]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:01 volumiosalon volumiobt[3621]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:01 volumiosalon volumiobt[3621]: Exception: Bluetooth adapter not found Aug 30 21:51:01 volumiosalon systemd[1]: volumiobt.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:51:01 volumiosalon systemd[1]: volumiobt.service: Failed with result 'exit-code'. Aug 30 21:51:01 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:51:01 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:51:01 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 21:51:01 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 21:51:01 volumiosalon volumio[1026]: info: Discovery: Getting this device information Aug 30 21:51:01 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:51:01 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:51:01 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 21:51:01 volumiosalon volumio[1026]: verbose: New Socket.io Connection to 10.0.1.53:3000 from 10.0.1.204 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Aug 30 21:51:01 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 21:51:01 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 21:51:02 volumiosalon systemd[1]: volumiobt.service: Scheduled restart job, restart counter is at 3. Aug 30 21:51:02 volumiosalon systemd[1]: Stopped volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:02 volumiosalon systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:02 volumiosalon volumiobt[3624]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 21:51:02 volumiosalon sudo[3625]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 21:51:02 volumiosalon sudo[3625]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:02 volumiosalon sudo[3625]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:02 volumiosalon sudo[3627]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 21:51:02 volumiosalon sudo[3627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:02 volumiosalon sudo[3627]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:02 volumiosalon volumiobt[3629]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 21:51:02 volumiosalon volumiobt[3632]: No default controller available Aug 30 21:51:03 volumiosalon volumiobt[3897]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 30 21:51:03 volumiosalon volumiobt[3899]: [83B blob data] Aug 30 21:51:03 volumiosalon volumiobt[3899]: No default controller available Aug 30 21:51:03 volumiosalon volumiobt[3899]: [bluetoothctl]> pairable on Aug 30 21:51:03 volumiosalon volumiobt[3899]: No default controller available Aug 30 21:51:03 volumiosalon volumiobt[3899]: [bluetoothctl]> Aug 30 21:51:03 volumiosalon volumiobt[3910]: INFO [BTSTART] Registering Bluetooth agent... Aug 30 21:51:03 volumiosalon volumiobt[3917]: No agent is registered Aug 30 21:51:03 volumiosalon volumiobt[3923]: INFO [BTSTART] Agent registered successfully. Aug 30 21:51:03 volumiosalon volumiobt[3926]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 30 21:51:03 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 21:51:03 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 79. Aug 30 21:51:03 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:51:03 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:51:03 volumiosalon volumio[1026]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Aug 30 21:51:03 volumiosalon go-librespot[3955]: go-librespot daemon starting... Aug 30 21:51:03 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:03+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:51:03 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:03+02:00" level=debug msg="app state loaded" Aug 30 21:51:03 volumiosalon volumio[1026]: error: Error getting DISCID: Error: Command failed: /usr/bin/abcde -a cddb -N -d /dev/sr0 Aug 30 21:51:03 volumiosalon volumio[1026]: which: no oggenc in (/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin) Aug 30 21:51:03 volumiosalon volumio[1026]: Selected: #1 (Kult / Posłuchaj to do Ciebie) Aug 30 21:51:03 volumiosalon volumio[1026]: Edit selected CDDB data [y/N]? Aug 30 21:51:03 volumiosalon volumio[1026]: Is the CD multi-artist [y/N]? n Aug 30 21:51:03 volumiosalon volumio[1026]: info: Could not get CDDB Entry for unknown DiscID Aug 30 21:51:03 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:03+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:51:03 volumiosalon volumio[1026]: error: GETCD INFO Cannot read CDDB file Error: EISDIR: illegal operation on a directory, read Aug 30 21:51:03 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 21:51:03 volumiosalon volumio[1026]: info: [1788119463700] CoreMusicLibrary::Adding element Audio CD Aug 30 21:51:03 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 21:51:03 volumiosalon volumio[1026]: Cannot find translation for source RADIO 357 Aug 30 21:51:03 volumiosalon volumio[1026]: Cannot find translation for source Radio Browser Aug 30 21:51:03 volumiosalon volumio[1026]: Cannot find translation for source Audio CD Aug 30 21:51:03 volumiosalon upmpdcli[3975]: writing RSA key Aug 30 21:51:03 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:51:03 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:51:03 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:03+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 21:51:03 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:03+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 21:51:03 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:03+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 21:51:03 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:03+02:00" level=info msg="zeroconf server listening on port 41267" Aug 30 21:51:03 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:03+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 21:51:03 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:03.995+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.309468ms platform=PLATFORM_IOS version=6.260807.0 Aug 30 21:51:03 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:03.996+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-254.343µs timeout=20s Aug 30 21:51:03 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:03.996+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" Aug 30 21:51:03 volumiosalon volumiobt[3929]: 2026-08-30 21:51:03 a2dp-agent [INFO] Connecting to system D-Bus Aug 30 21:51:04 volumiosalon volumiobt[3929]: 2026-08-30 21:51:04 a2dp-agent [INFO] Connected to system D-Bus Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 21:51:04 volumiosalon volumiobt[3929]: 2026-08-30 21:51:04 a2dp-agent [ERROR] No Bluetooth adapter found: Bluetooth adapter not found Aug 30 21:51:04 volumiosalon volumio[1026]: info: Received Get System Info Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 21:51:04 volumiosalon volumio[1026]: info: Discovery: Getting this device information Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:51:04 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 21:51:04 volumiosalon volumiobt[3929]: 2026-08-30 21:51:04 a2dp-agent [ERROR] Agent crashed: Bluetooth adapter not found Aug 30 21:51:04 volumiosalon volumiobt[3929]: Traceback (most recent call last): Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:04 volumiosalon volumiobt[3929]: asyncio.run(_run()) Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:04 volumiosalon volumiobt[3929]: return runner.run(main) Aug 30 21:51:04 volumiosalon volumiobt[3929]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:04 volumiosalon volumiobt[3929]: return self._loop.run_until_complete(task) Aug 30 21:51:04 volumiosalon volumiobt[3929]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:04 volumiosalon volumiobt[3929]: return future.result() Aug 30 21:51:04 volumiosalon volumiobt[3929]: ^^^^^^^^^^^^^^^ Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:04 volumiosalon volumiobt[3929]: adapter_path = await find_adapter(bus) Aug 30 21:51:04 volumiosalon volumiobt[3929]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:04 volumiosalon volumiobt[3929]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:04 volumiosalon volumiobt[3929]: Exception: Bluetooth adapter not found Aug 30 21:51:04 volumiosalon volumiobt[3929]: Traceback (most recent call last): Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/bin/bt/a2dp-agent", line 234, in Aug 30 21:51:04 volumiosalon volumiobt[3929]: main() Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:04 volumiosalon volumiobt[3929]: asyncio.run(_run()) Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:04 volumiosalon volumiobt[3929]: return runner.run(main) Aug 30 21:51:04 volumiosalon volumiobt[3929]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:04 volumiosalon volumiobt[3929]: return self._loop.run_until_complete(task) Aug 30 21:51:04 volumiosalon volumiobt[3929]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:04 volumiosalon volumiobt[3929]: return future.result() Aug 30 21:51:04 volumiosalon volumiobt[3929]: ^^^^^^^^^^^^^^^ Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:04 volumiosalon volumiobt[3929]: adapter_path = await find_adapter(bus) Aug 30 21:51:04 volumiosalon volumiobt[3929]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:04 volumiosalon volumiobt[3929]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.031+02:00 level=INFO msg="emitting device name changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" name=VolumioSalon Aug 30 21:51:04 volumiosalon volumiobt[3929]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:04 volumiosalon volumiobt[3929]: Exception: Bluetooth adapter not found Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.038+02:00 level=INFO msg="emitting device language changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" language=en Aug 30 21:51:04 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:04+02:00" level=debug msg="obtained new client token: AAEOJj05c7Hmv4jOco9kBzVwVgvIsX6cJD/MPFoiV9JrL2WPIo2CVRgyZjY7D/06DR8zmntcADSY2ZENk1asHnvRFGUztPWNe2yQDW55G7aIFWSsr/M2tSzua2EjCafsAjbcbfyMDF184CvS5XaQelx+Dk8tprsiLKt7MrWOyJosrLzaPfn0w4wG2R2tFeUqFuE0pK5JAafBwpQ5WeLjyNWKzmFHndV33sFjVJO91joMToHh93fU" Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.051+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" timezone=Europe/Warsaw Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.057+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" available=true connected=true macAddress=00:8c:fa:d4:1c:84 ip4Address=10.0.1.53/24 ip6Address= Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.060+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" available=false connected=false macAddress= ip4Address= ip6Address= ssid= Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.061+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" setupComplete=true Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 30 21:51:04 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:04+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 30 21:51:04 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:04+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Aug 30 21:51:04 volumiosalon systemd[1]: volumiobt.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:51:04 volumiosalon systemd[1]: volumiobt.service: Failed with result 'exit-code'. Aug 30 21:51:04 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:04+02:00" level=debug msg="completed keyexchange" Aug 30 21:51:04 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:04+02:00" level=debug msg="completed challenge" Aug 30 21:51:04 volumiosalon volumio[1026]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 1 -D 0 Aug 30 21:51:04 volumiosalon volumio[1026]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 30 21:51:04 volumiosalon volumio[1026]: {"cmd":"/usr/local/bin/alsacap -C 1 -D 0","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 1 -D 0\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 30 21:51:04 volumiosalon volumio[1026]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 0 -D 7 Aug 30 21:51:04 volumiosalon volumio[1026]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 30 21:51:04 volumiosalon volumio[1026]: {"cmd":"/usr/local/bin/alsacap -C 0 -D 7","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 0 -D 7\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 30 21:51:04 volumiosalon volumio[1026]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 0 -D 3 Aug 30 21:51:04 volumiosalon volumio[1026]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 30 21:51:04 volumiosalon volumio[1026]: {"cmd":"/usr/local/bin/alsacap -C 0 -D 3","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 0 -D 3\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 30 21:51:04 volumiosalon volumio[1026]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Aug 30 21:51:04 volumiosalon volumio[1026]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 30 21:51:04 volumiosalon volumio[1026]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 30 21:51:04 volumiosalon volumio[1026]: amixer -c 5 info | grep "NuForce µDAC 2" Aug 30 21:51:04 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:04+02:00" level=info msg="authenticated AP" username="vo***kh" Aug 30 21:51:04 volumiosalon volumio[1026]: Card sysdefault:5 'N2'/'NuForce NuForce µDAC 2 at usb-0000:00:12.0-2, full speed' Aug 30 21:51:04 volumiosalon volumio[1026]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Aug 30 21:51:04 volumiosalon volumio[1026]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 30 21:51:04 volumiosalon volumio[1026]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 30 21:51:04 volumiosalon volumio[1026]: amixer -c 5 info | grep "NuForce µDAC 2" Aug 30 21:51:04 volumiosalon systemd[1]: volumiobt.service: Scheduled restart job, restart counter is at 4. Aug 30 21:51:04 volumiosalon systemd[1]: Stopped volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:04 volumiosalon systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:04 volumiosalon volumiobt[4110]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 21:51:04 volumiosalon volumio[1026]: Card sysdefault:5 'N2'/'NuForce NuForce µDAC 2 at usb-0000:00:12.0-2, full speed' Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.337+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" selectedOutputId=5 Aug 30 21:51:04 volumiosalon sudo[4118]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 21:51:04 volumiosalon sudo[4118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:04 volumiosalon sudo[4118]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:04 volumiosalon volumio[1026]: info: Received Get System Info Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 21:51:04 volumiosalon volumio[1026]: info: Discovery: Getting this device information Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:51:04 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 21:51:04 volumiosalon sudo[4127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 21:51:04 volumiosalon sudo[4127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.393+02:00 level=INFO msg="emitting software info changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" currentVersion=4.119 latestVersion=4.119 Aug 30 21:51:04 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:04.394+02:00 level=INFO msg="emitting software update progress event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" status=UPDATE_STATUS_NONE progress=0 Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 21:51:04 volumiosalon sudo[4127]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:04 volumiosalon go-librespot[3956]: time="2026-08-30T21:51:04+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 21:51:04 volumiosalon volumiobt[4139]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 21:51:04 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:51:04 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:51:04 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 30 21:51:04 volumiosalon volumiobt[4152]: No default controller available Aug 30 21:51:04 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:51:04 volumiosalon volumio[1026]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:51:05 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:05.358+02:00 level=INFO msg="authenticated Firebase client" component=volumio/firebase userId=WOByxcY2ydfQH0eXebNLMZB7iEj2 tokenExpiry=2026-08-30T22:51:05.358+02:00 Aug 30 21:51:05 volumiosalon volumiobt[4192]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 30 21:51:05 volumiosalon volumiobt[4193]: [83B blob data] Aug 30 21:51:05 volumiosalon volumiobt[4193]: No default controller available Aug 30 21:51:05 volumiosalon volumiobt[4193]: [bluetoothctl]> pairable on Aug 30 21:51:05 volumiosalon volumiobt[4193]: No default controller available Aug 30 21:51:05 volumiosalon volumiobt[4193]: [bluetoothctl]> Aug 30 21:51:05 volumiosalon volumiobt[4194]: INFO [BTSTART] Registering Bluetooth agent... Aug 30 21:51:05 volumiosalon volumiobt[4196]: No agent is registered Aug 30 21:51:05 volumiosalon volumiobt[4197]: INFO [BTSTART] Agent registered successfully. Aug 30 21:51:05 volumiosalon volumiobt[4198]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 30 21:51:05 volumiosalon volumiobt[4199]: 2026-08-30 21:51:05 a2dp-agent [INFO] Connecting to system D-Bus Aug 30 21:51:05 volumiosalon volumiobt[4199]: 2026-08-30 21:51:05 a2dp-agent [INFO] Connected to system D-Bus Aug 30 21:51:05 volumiosalon volumiobt[4199]: 2026-08-30 21:51:05 a2dp-agent [ERROR] No Bluetooth adapter found: Bluetooth adapter not found Aug 30 21:51:05 volumiosalon volumiobt[4199]: 2026-08-30 21:51:05 a2dp-agent [ERROR] Agent crashed: Bluetooth adapter not found Aug 30 21:51:05 volumiosalon volumiobt[4199]: Traceback (most recent call last): Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:05 volumiosalon volumiobt[4199]: asyncio.run(_run()) Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:05 volumiosalon volumiobt[4199]: return runner.run(main) Aug 30 21:51:05 volumiosalon volumiobt[4199]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:05 volumiosalon volumiobt[4199]: return self._loop.run_until_complete(task) Aug 30 21:51:05 volumiosalon volumiobt[4199]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:05 volumiosalon volumiobt[4199]: return future.result() Aug 30 21:51:05 volumiosalon volumiobt[4199]: ^^^^^^^^^^^^^^^ Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:05 volumiosalon volumiobt[4199]: adapter_path = await find_adapter(bus) Aug 30 21:51:05 volumiosalon volumiobt[4199]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:05 volumiosalon volumiobt[4199]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:05 volumiosalon volumiobt[4199]: Exception: Bluetooth adapter not found Aug 30 21:51:05 volumiosalon volumiobt[4199]: Traceback (most recent call last): Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/bin/bt/a2dp-agent", line 234, in Aug 30 21:51:05 volumiosalon volumiobt[4199]: main() Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:05 volumiosalon volumiobt[4199]: asyncio.run(_run()) Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:05 volumiosalon volumiobt[4199]: return runner.run(main) Aug 30 21:51:05 volumiosalon volumiobt[4199]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:05 volumiosalon volumiobt[4199]: return self._loop.run_until_complete(task) Aug 30 21:51:05 volumiosalon volumiobt[4199]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:05 volumiosalon volumiobt[4199]: return future.result() Aug 30 21:51:05 volumiosalon volumiobt[4199]: ^^^^^^^^^^^^^^^ Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:05 volumiosalon volumiobt[4199]: adapter_path = await find_adapter(bus) Aug 30 21:51:05 volumiosalon volumiobt[4199]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:05 volumiosalon volumiobt[4199]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:05 volumiosalon volumiobt[4199]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:05 volumiosalon volumiobt[4199]: Exception: Bluetooth adapter not found Aug 30 21:51:06 volumiosalon systemd[1]: volumiobt.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:51:06 volumiosalon systemd[1]: volumiobt.service: Failed with result 'exit-code'. Aug 30 21:51:06 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:06.079+02:00 level=INFO msg="emitting user changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" userId=WOByxcY2ydfQH0eXebNLMZB7iEj2 Aug 30 21:51:06 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 21:51:06 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 21:51:06 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 30 21:51:06 volumiosalon systemd[1]: volumiobt.service: Scheduled restart job, restart counter is at 5. Aug 30 21:51:06 volumiosalon systemd[1]: Stopped volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:06 volumiosalon systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:06 volumiosalon volumiobt[4202]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 21:51:06 volumiosalon sudo[4203]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 21:51:06 volumiosalon sudo[4203]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:06 volumiosalon sudo[4203]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:06 volumiosalon sudo[4205]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 21:51:06 volumiosalon sudo[4205]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:06 volumiosalon sudo[4205]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:06 volumiosalon volumiobt[4207]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 21:51:06 volumiosalon volumiobt[4210]: No default controller available Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.053+02:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.053+02:00 level=INFO msg="emitting music providers changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" providers=9 Aug 30 21:51:07 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 21:51:07 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 21:51:07 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 30 21:51:07 volumiosalon volumiobt[4213]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.421+02:00 level=INFO msg="emitting plugins changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" plugins=53 Aug 30 21:51:07 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:51:07 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.428+02:00 level=INFO msg="emitting player state changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" state=STATUS_STOPPED positionMs=0 volume=100 Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.429+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="10.0.1.204:63996 @ 0xc0002cbc50" id=http://stream.rcs.revma.com/ypqt40u0x1zuv title="Radio Nowy Swiat" Aug 30 21:51:07 volumiosalon volumiobt[4214]: [83B blob data] Aug 30 21:51:07 volumiosalon volumiobt[4214]: No default controller available Aug 30 21:51:07 volumiosalon volumiobt[4214]: [bluetoothctl]> pairable on Aug 30 21:51:07 volumiosalon volumiobt[4214]: No default controller available Aug 30 21:51:07 volumiosalon volumiobt[4214]: [bluetoothctl]> Aug 30 21:51:07 volumiosalon volumiobt[4215]: INFO [BTSTART] Registering Bluetooth agent... Aug 30 21:51:07 volumiosalon volumiobt[4217]: No agent is registered Aug 30 21:51:07 volumiosalon volumiobt[4218]: INFO [BTSTART] Agent registered successfully. Aug 30 21:51:07 volumiosalon volumiobt[4219]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.509+02:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-2.10929ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.528+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s Aug 30 21:51:07 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 80. Aug 30 21:51:07 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:51:07 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 21:51:07 volumiosalon go-librespot[4230]: go-librespot daemon starting... Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=debug msg="app state loaded" Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.679+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=http://pushupdates.volumio.org duration=143.436451ms Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.680+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=146.116945ms Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.680+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://functions.volumio.cloud duration=152.223854ms Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.699+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://functions.volumio.cloud duration=153.916383ms Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.720+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=191.970377ms Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.757+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=226.581529ms Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.783+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://www.googleapis.com duration=252.354246ms Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.808+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=278.737845ms Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.819+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://securetoken.googleapis.com duration=287.85297ms Aug 30 21:51:07 volumiosalon volumio[1026]: info: Initializing connection to go-librespot Websocket Aug 30 21:51:07 volumiosalon volumio[1026]: info: Connection to go-librespot Websocket established Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=debug msg="new websocket client" Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=info msg="zeroconf server listening on port 42409" Aug 30 21:51:07 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:07+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 21:51:07 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:07.925+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://database.volumio.cloud duration=384.94288ms Aug 30 21:51:07 volumiosalon volumiobt[4220]: 2026-08-30 21:51:07 a2dp-agent [INFO] Connecting to system D-Bus Aug 30 21:51:07 volumiosalon volumiobt[4220]: 2026-08-30 21:51:07 a2dp-agent [INFO] Connected to system D-Bus Aug 30 21:51:07 volumiosalon volumiobt[4220]: 2026-08-30 21:51:07 a2dp-agent [ERROR] No Bluetooth adapter found: Bluetooth adapter not found Aug 30 21:51:07 volumiosalon volumiobt[4220]: 2026-08-30 21:51:07 a2dp-agent [ERROR] Agent crashed: Bluetooth adapter not found Aug 30 21:51:07 volumiosalon volumiobt[4220]: Traceback (most recent call last): Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:07 volumiosalon volumiobt[4220]: asyncio.run(_run()) Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:07 volumiosalon volumiobt[4220]: return runner.run(main) Aug 30 21:51:07 volumiosalon volumiobt[4220]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:07 volumiosalon volumiobt[4220]: return self._loop.run_until_complete(task) Aug 30 21:51:07 volumiosalon volumiobt[4220]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:07 volumiosalon volumiobt[4220]: return future.result() Aug 30 21:51:07 volumiosalon volumiobt[4220]: ^^^^^^^^^^^^^^^ Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:07 volumiosalon volumiobt[4220]: adapter_path = await find_adapter(bus) Aug 30 21:51:07 volumiosalon volumiobt[4220]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:07 volumiosalon volumiobt[4220]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:07 volumiosalon volumiobt[4220]: Exception: Bluetooth adapter not found Aug 30 21:51:07 volumiosalon volumiobt[4220]: Traceback (most recent call last): Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/bin/bt/a2dp-agent", line 234, in Aug 30 21:51:07 volumiosalon volumiobt[4220]: main() Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:07 volumiosalon volumiobt[4220]: asyncio.run(_run()) Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:07 volumiosalon volumiobt[4220]: return runner.run(main) Aug 30 21:51:07 volumiosalon volumiobt[4220]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:07 volumiosalon volumiobt[4220]: return self._loop.run_until_complete(task) Aug 30 21:51:07 volumiosalon volumiobt[4220]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:07 volumiosalon volumiobt[4220]: return future.result() Aug 30 21:51:07 volumiosalon volumiobt[4220]: ^^^^^^^^^^^^^^^ Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:07 volumiosalon volumiobt[4220]: adapter_path = await find_adapter(bus) Aug 30 21:51:07 volumiosalon volumiobt[4220]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:07 volumiosalon volumiobt[4220]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:07 volumiosalon volumiobt[4220]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:07 volumiosalon volumiobt[4220]: Exception: Bluetooth adapter not found Aug 30 21:51:08 volumiosalon systemd[1]: volumiobt.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:51:08 volumiosalon systemd[1]: volumiobt.service: Failed with result 'exit-code'. Aug 30 21:51:08 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:08+02:00" level=debug msg="obtained new client token: AAFCRyLWYS1VQ677OiGQFGpKrRpIUWxExz9MpOPJVhXGa8vQdd6+L800Az9GlrpS7L3CekthysSL5q31F3sxvD+5+onrNBY6jQJjq2QiTFG1gu4J+9xye+ShFCSGCHl/bUdDqEKA2OB++6jUOd9brzourJ70mp9ycqkuPImV03ACogw9AAz2YQQyZpsBvnTdYZcjRBdJLA05H/+PXd303IJCHbQT+YPBkv1InulSh+/DcII7LnXG" Aug 30 21:51:08 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:08+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 21:51:08 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:08.131+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=http://cddb.volumio.org duration=593.942401ms Aug 30 21:51:08 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:08+02:00" level=debug msg="completed keyexchange" Aug 30 21:51:08 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:08+02:00" level=debug msg="completed challenge" Aug 30 21:51:08 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:08+02:00" level=info msg="authenticated AP" username="vo***kh" Aug 30 21:51:08 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:08.249+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=http://plugins.volumio.org duration=713.340975ms Aug 30 21:51:08 volumiosalon systemd[1]: volumiobt.service: Scheduled restart job, restart counter is at 6. Aug 30 21:51:08 volumiosalon systemd[1]: Stopped volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:08 volumiosalon systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:08 volumiosalon go-librespot[4231]: time="2026-08-30T21:51:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 21:51:08 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:51:08 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 21:51:08 volumiosalon volumiobt[4243]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 21:51:08 volumiosalon volumio[1026]: info: Connection to go-librespot Websocket closed Aug 30 21:51:08 volumiosalon sudo[4244]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 21:51:08 volumiosalon sudo[4244]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:08 volumiosalon sudo[4244]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:08 volumiosalon sudo[4246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 21:51:08 volumiosalon sudo[4246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:08 volumiosalon sudo[4246]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:08 volumiosalon volumio5-onboarding[1621]: time=2026-08-30T21:51:08.412+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="10.0.1.204:63996 @ 0xc0002cbc50" latency=-1.95329ms timeout=10s endpoint=https://google.com duration=883.974782ms Aug 30 21:51:08 volumiosalon volumiobt[4248]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 21:51:08 volumiosalon volumiobt[4251]: No default controller available Aug 30 21:51:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 21:51:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 21:51:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 30 21:51:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 30 21:51:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 30 21:51:08 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetBrowseSources Aug 30 21:51:08 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 21:51:08 volumiosalon sudo[4255]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 21:51:08 volumiosalon sudo[4255]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:08 volumiosalon sudo[4255]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:08 volumiosalon sudo[4257]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 21:51:09 volumiosalon sudo[4257]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:09 volumiosalon sudo[4257]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:09 volumiosalon volumio[1026]: verbose: New Socket.io Connection to 10.0.1.53 from 10.0.1.204 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Aug 30 21:51:09 volumiosalon sudo[4264]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 21:51:09 volumiosalon sudo[4264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:09 volumiosalon sudo[4266]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 21:51:09 volumiosalon sudo[4266]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:09 volumiosalon sudo[4264]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:09 volumiosalon sudo[4266]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:09 volumiosalon volumio[1026]: verbose: New Socket.io Connection to 10.0.1.53 from 10.0.1.204 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Aug 30 21:51:09 volumiosalon volumio[1026]: info: CoreCommandRouter::volumioGetState Aug 30 21:51:09 volumiosalon volumio[1026]: info: CorePlayQueue::getTrack 0 Aug 30 21:51:09 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 30 21:51:09 volumiosalon volumio[1026]: info: Listing playlists Aug 30 21:51:09 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 30 21:51:09 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 21:51:09 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 21:51:09 volumiosalon volumio[1026]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 21:51:09 volumiosalon volumiobt[4271]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 30 21:51:09 volumiosalon volumiobt[4272]: [83B blob data] Aug 30 21:51:09 volumiosalon volumiobt[4272]: No default controller available Aug 30 21:51:09 volumiosalon volumiobt[4272]: [bluetoothctl]> pairable on Aug 30 21:51:09 volumiosalon volumiobt[4272]: No default controller available Aug 30 21:51:09 volumiosalon volumiobt[4272]: [bluetoothctl]> Aug 30 21:51:09 volumiosalon volumiobt[4273]: INFO [BTSTART] Registering Bluetooth agent... Aug 30 21:51:09 volumiosalon volumiobt[4275]: No agent is registered Aug 30 21:51:09 volumiosalon volumiobt[4276]: INFO [BTSTART] Agent registered successfully. Aug 30 21:51:09 volumiosalon volumiobt[4277]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 30 21:51:09 volumiosalon volumiobt[4278]: 2026-08-30 21:51:09 a2dp-agent [INFO] Connecting to system D-Bus Aug 30 21:51:09 volumiosalon volumiobt[4278]: 2026-08-30 21:51:09 a2dp-agent [INFO] Connected to system D-Bus Aug 30 21:51:09 volumiosalon volumiobt[4278]: 2026-08-30 21:51:09 a2dp-agent [ERROR] No Bluetooth adapter found: Bluetooth adapter not found Aug 30 21:51:09 volumiosalon volumiobt[4278]: 2026-08-30 21:51:09 a2dp-agent [ERROR] Agent crashed: Bluetooth adapter not found Aug 30 21:51:09 volumiosalon volumiobt[4278]: Traceback (most recent call last): Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:09 volumiosalon volumiobt[4278]: asyncio.run(_run()) Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:09 volumiosalon volumiobt[4278]: return runner.run(main) Aug 30 21:51:09 volumiosalon volumiobt[4278]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:09 volumiosalon volumiobt[4278]: return self._loop.run_until_complete(task) Aug 30 21:51:09 volumiosalon volumiobt[4278]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:09 volumiosalon volumiobt[4278]: return future.result() Aug 30 21:51:09 volumiosalon volumiobt[4278]: ^^^^^^^^^^^^^^^ Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:09 volumiosalon volumiobt[4278]: adapter_path = await find_adapter(bus) Aug 30 21:51:09 volumiosalon volumiobt[4278]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:09 volumiosalon volumiobt[4278]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:09 volumiosalon volumiobt[4278]: Exception: Bluetooth adapter not found Aug 30 21:51:09 volumiosalon volumiobt[4278]: Traceback (most recent call last): Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/bin/bt/a2dp-agent", line 234, in Aug 30 21:51:09 volumiosalon volumiobt[4278]: main() Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/bin/bt/a2dp-agent", line 225, in main Aug 30 21:51:09 volumiosalon volumiobt[4278]: asyncio.run(_run()) Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run Aug 30 21:51:09 volumiosalon volumiobt[4278]: return runner.run(main) Aug 30 21:51:09 volumiosalon volumiobt[4278]: ^^^^^^^^^^^^^^^^ Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run Aug 30 21:51:09 volumiosalon volumiobt[4278]: return self._loop.run_until_complete(task) Aug 30 21:51:09 volumiosalon volumiobt[4278]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete Aug 30 21:51:09 volumiosalon volumiobt[4278]: return future.result() Aug 30 21:51:09 volumiosalon volumiobt[4278]: ^^^^^^^^^^^^^^^ Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/bin/bt/a2dp-agent", line 175, in _run Aug 30 21:51:09 volumiosalon volumiobt[4278]: adapter_path = await find_adapter(bus) Aug 30 21:51:09 volumiosalon volumiobt[4278]: ^^^^^^^^^^^^^^^^^^^^^^^ Aug 30 21:51:09 volumiosalon volumiobt[4278]: File "/usr/bin/bt/bluezutils.py", line 73, in find_adapter Aug 30 21:51:09 volumiosalon volumiobt[4278]: raise Exception("Bluetooth adapter not found") Aug 30 21:51:09 volumiosalon volumiobt[4278]: Exception: Bluetooth adapter not found Aug 30 21:51:10 volumiosalon systemd[1]: volumiobt.service: Main process exited, code=exited, status=1/FAILURE Aug 30 21:51:10 volumiosalon systemd[1]: volumiobt.service: Failed with result 'exit-code'. Aug 30 21:51:10 volumiosalon systemd[1]: volumiobt.service: Scheduled restart job, restart counter is at 7. Aug 30 21:51:10 volumiosalon systemd[1]: Stopped volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:10 volumiosalon systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 21:51:10 volumiosalon volumiobt[4281]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 21:51:10 volumiosalon sudo[4282]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 21:51:10 volumiosalon sudo[4282]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:10 volumiosalon sudo[4282]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:10 volumiosalon sudo[4284]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 21:51:10 volumiosalon sudo[4284]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 21:51:10 volumiosalon sudo[4284]: pam_unix(sudo:session): session closed for user root Aug 30 21:51:10 volumiosalon volumiobt[4286]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 21:51:10 volumiosalon volumiobt[4289]: No default controller available Aug 30 21:51:10 volumiosalon volumio[1026]: info: Getting Spotify volume Aug 30 21:51:10 volumiosalon volumio[1026]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 21:51:10 volumiosalon volumio[1026]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 21:51:10 volumiosalon volumio[1026]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 30 21:51:10 volumiosalon volumio[1026]: errno: -111, Aug 30 21:51:10 volumiosalon volumio[1026]: code: 'ECONNREFUSED', Aug 30 21:51:10 volumiosalon volumio[1026]: syscall: 'connect', Aug 30 21:51:10 volumiosalon volumio[1026]: address: '127.0.0.1', Aug 30 21:51:10 volumiosalon volumio[1026]: port: 9879, Aug 30 21:51:10 volumiosalon volumio[1026]: response: undefined Aug 30 21:51:10 volumiosalon volumio[1026]: } Aug 30 21:51:10 volumiosalon volumio[1026]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 21:51:11 volumiosalon sudo[4306]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-30 21:50' Aug 30 21:51:11 volumiosalon sudo[4306]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:45:45 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6bf7cd61fe53483b72878254df87f1c0"