Aug 27 19:10:48 daconpi ntpd[1061]: CLOCK: time stepped by 1381368.184071 Aug 27 19:10:48 daconpi ntpd[1061]: CLOCK: time changed from 2026-08-11 to 2026-08-27 Aug 27 19:10:48 daconpi ntpd[1061]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 27 19:10:48 daconpi systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Aug 27 19:10:48 daconpi systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Aug 27 19:10:48 daconpi systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Aug 27 19:10:48 daconpi systemd[1]: dpkg-db-backup.service: Deactivated successfully. Aug 27 19:10:48 daconpi systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Aug 27 19:10:48 daconpi volumio[1245]: info: Plugin mpdemulation is not enabled Aug 27 19:10:49 daconpi volumio[1245]: info: Loading plugin "rest_api"... Aug 27 19:10:49 daconpi volumio[1245]: info: Loading plugin "websocket"... Aug 27 19:10:49 daconpi volumio[1245]: info: Starting Socket.io Server version 1.7.4 Aug 27 19:10:49 daconpi volumio[1245]: info: Loading i18n strings for locale en Aug 27 19:10:49 daconpi volumio[1245]: Updating browse sources language Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:10:49 daconpi volumio[1466]: Forking 3 albumart workers Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::initPlayerControls Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 19:10:49 daconpi volumio[1245]: Express server listening on port 3000 Aug 27 19:10:49 daconpi volumio[1245]: [Metrics] WebUI: 9s 627.90ms Aug 27 19:10:49 daconpi volumio[1245]: info: CoreStateMachine::resetVolumioState Aug 27 19:10:49 daconpi volumio[1245]: info: CoreStateMachine::getcurrentVolume Aug 27 19:10:49 daconpi volumio[1245]: info: CoreCommandRouter::volumioRetrievevolume Aug 27 19:10:49 daconpi volumio[1245]: info: Cannot read play queue from file Aug 27 19:10:49 daconpi volumio[1245]: info: Volumio Network Manager: Network status updated: 2 Aug 27 19:10:50 daconpi volumio-remote-updater[836]: [2026-08-27 19:10:50] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1786501679 101 Aug 27 19:10:50 daconpi volumio[1245]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Aug 27 19:10:50 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:10:50 daconpi volumio[1245]: info: VolumeController:: Volume=33 Mute =false Aug 27 19:10:50 daconpi volumio[1245]: info: CoreStateMachine::pushState Aug 27 19:10:50 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:50 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 19:10:50 daconpi volumio[1245]: info: CoreCommandRouter::volumioPushState Aug 27 19:10:50 daconpi volumio[1245]: info: CoreStateMachine::updateTrackBlock Aug 27 19:10:50 daconpi volumio[1245]: info: CorePlayQueue::getTrackBlock Aug 27 19:10:50 daconpi volumio[1245]: info: CoreCommandRouter::volumioRetrievevolume Aug 27 19:10:50 daconpi volumio[1245]: info: CoreStateMachine::setRepeat null single undefined Aug 27 19:10:50 daconpi volumio[1245]: info: CoreStateMachine::pushState Aug 27 19:10:50 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:50 daconpi volumio[1245]: info: CoreCommandRouter::volumioPushState Aug 27 19:10:50 daconpi volumio[1245]: info: CoreStateMachine::setRandom null Aug 27 19:10:50 daconpi volumio[1245]: info: CoreStateMachine::pushState Aug 27 19:10:50 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:50 daconpi volumio[1245]: info: CoreCommandRouter::volumioPushState Aug 27 19:10:50 daconpi volumio[1245]: info: Setting Device type: Raspberry PI Aug 27 19:10:50 daconpi volumio[1245]: info: Completed loading Core Plugins Aug 27 19:10:50 daconpi volumio[1245]: info: Preparing to generate the ALSA configuration file Aug 27 19:10:50 daconpi volumio[1245]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Aug 27 19:10:50 daconpi volumio[1245]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Aug 27 19:10:50 daconpi volumio[1245]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Aug 27 19:10:51 daconpi volumio[1245]: info: VolumeController:: Volume=33 Mute =false Aug 27 19:10:51 daconpi volumio[1245]: info: CoreStateMachine::pushState Aug 27 19:10:51 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::volumioPushState Aug 27 19:10:51 daconpi volumio[1245]: info: Discovery: A device disappeared from network Aug 27 19:10:51 daconpi volumio[1245]: info: Discovery: A device disappeared from network Aug 27 19:10:51 daconpi volumio[1245]: info: Discovery: adding 6302485a-c0ec-4bf8-a51e-3e64c3aef8ee Aug 27 19:10:51 daconpi volumio[1245]: info: Discovery: Found device DacOnPi Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:51 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:51 daconpi volumio[1245]: info: Discovery: this is already registered, 6302485a-c0ec-4bf8-a51e-3e64c3aef8ee Aug 27 19:10:51 daconpi volumio[1245]: info: Discovery: Found device DacOnPi Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:51 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:51 daconpi volumio[1245]: info: Discovery: this is already registered, 6302485a-c0ec-4bf8-a51e-3e64c3aef8ee Aug 27 19:10:51 daconpi volumio[1245]: info: Discovery: Found device DacOnPi Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:51 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:51 daconpi volumio[1245]: info: Asound.conf file unchanged, so no further update is needed Aug 27 19:10:51 daconpi volumio[1245]: info: Output device has changed, restarting MPD Aug 27 19:10:51 daconpi volumio[1245]: info: Output device has changed, restarting Shairport Sync Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:10:51 daconpi sudo[1536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 27 19:10:51 daconpi sudo[1536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:51 daconpi sudo[1538]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 27 19:10:51 daconpi sudo[1538]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:51 daconpi sudo[1536]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:51 daconpi ntpd[1061]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: Pool taking: 198.181.199.84 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: Pool taking: 206.108.0.133 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: Pool taking: 216.232.132.18 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: Pool taking: 162.159.200.1 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: Pool taking: 2607:5300:61:4a3::1 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: Pool taking: 2600:1f11:a50:1100::be00:4 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: Pool taking: 2605:e440:6::1:384 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: Pool taking: 2607:4100:2:ff::2 Aug 27 19:10:51 daconpi ntpd[1061]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Aug 27 19:10:51 daconpi volumio[1245]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 27 19:10:51 daconpi volumio[1245]: info: ___________ START PLUGINS ___________ Aug 27 19:10:51 daconpi volumio[1245]: info: ControllerMpd::onStart: Initializing MPD Aug 27 19:10:51 daconpi volumio[1245]: info: Creating MPD Configuration file Aug 27 19:10:51 daconpi systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 27 19:10:51 daconpi systemd[1]: Starting mpd.service - Music Player Daemon... Aug 27 19:10:51 daconpi sudo[1547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 27 19:10:51 daconpi sudo[1547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 19:10:51 daconpi volumio[1245]: info: [1787883051575] CoreMusicLibrary::Adding element Media Servers Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:10:51 daconpi volumio[1245]: info: UPNP Browser: Client initialized successfully Aug 27 19:10:51 daconpi sudo[1550]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 27 19:10:51 daconpi sudo[1550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:51 daconpi sudo[1553]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 27 19:10:51 daconpi sudo[1553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:51 daconpi sudo[1550]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:10:51 daconpi sudo[1549]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 27 19:10:51 daconpi sudo[1549]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 27 19:10:51 daconpi sudo[1561]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 27 19:10:51 daconpi sudo[1549]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:51 daconpi volumio[1245]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:10:51 daconpi volumio[1245]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 19:10:51 daconpi volumio[1245]: info: [1787883051720] CoreMusicLibrary::Adding element Last_100 Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 19:10:51 daconpi volumio[1245]: info: [1787883051723] CoreMusicLibrary::Adding element Webradio Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:10:51 daconpi systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 27 19:10:51 daconpi sudo[1547]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:51 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 19:10:51 daconpi volumio[1245]: info: Initializing BBC Radios Aug 27 19:10:51 daconpi systemd[1]: mpd.service: Deactivated successfully. Aug 27 19:10:51 daconpi systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 27 19:10:51 daconpi systemd[1]: mpd.socket: Deactivated successfully. Aug 27 19:10:51 daconpi systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 27 19:10:51 daconpi systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 27 19:10:51 daconpi systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 27 19:10:51 daconpi systemd[1]: Starting mpd.service - Music Player Daemon... Aug 27 19:10:51 daconpi sudo[1569]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 27 19:10:51 daconpi sudo[1569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 27 19:10:51 daconpi sudo[1577]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 27 19:10:51 daconpi sudo[1569]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:52 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:52.170-07:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 27 19:10:52 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 19:10:52 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:10:52 daconpi systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 27 19:10:52 daconpi volumio[1245]: info: Creating Spotify config file Aug 27 19:10:52 daconpi ntpd[1061]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 27 19:10:52 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:52 daconpi ntpd[1061]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Aug 27 19:10:52 daconpi ntpd[1061]: DNS: Pool taking: 216.232.132.63 Aug 27 19:10:52 daconpi ntpd[1061]: DNS: Pool taking: 147.189.136.126 Aug 27 19:10:52 daconpi ntpd[1061]: DNS: Pool taking: 54.39.23.64 Aug 27 19:10:52 daconpi ntpd[1061]: DNS: Pool taking: 158.69.193.108 Aug 27 19:10:52 daconpi ntpd[1061]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Aug 27 19:10:53 daconpi dhcpcd[748]: timed out Aug 27 19:10:53 daconpi sh[711]: timed out Aug 27 19:10:53 daconpi sh[639]: ifup: failed to bring up eth0 Aug 27 19:10:53 daconpi systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:10:53 daconpi systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Aug 27 19:10:53 daconpi ntpd[1061]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 27 19:10:53 daconpi volumio[1486]: Starting albumart workers Aug 27 19:10:54 daconpi volumio[1245]: info: Volumio Calling Home Aug 27 19:10:54 daconpi systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 27 19:10:55 daconpi systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 27 19:10:55 daconpi systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:10:55 daconpi systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:10:55 daconpi upmpdcli[1617]: Could not open config: /tmp/upmpdcli.conf Aug 27 19:10:55 daconpi systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:10:55 daconpi systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 27 19:10:55 daconpi volumio[1490]: Starting albumart workers Aug 27 19:10:56 daconpi volumio[1487]: Starting albumart workers Aug 27 19:10:56 daconpi sudo[1619]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 27 19:10:56 daconpi sudo[1619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:56 daconpi volumio[1245]: info: Discovery: this is already registered, 6302485a-c0ec-4bf8-a51e-3e64c3aef8ee Aug 27 19:10:56 daconpi volumio[1245]: info: Discovery: Found device DacOnPi Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:56 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:56 daconpi sudo[1621]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 27 19:10:56 daconpi mpd[1578]: 2026-08-27T19:10:56 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 27 19:10:56 daconpi systemd[1]: Started mpd.service - Music Player Daemon. Aug 27 19:10:56 daconpi sudo[1538]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:56 daconpi sudo[1553]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:56 daconpi sudo[1619]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:56 daconpi sudo[1621]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:56 daconpi sudo[1621]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:56 daconpi volumio[1245]: info: MPD Permissions set Aug 27 19:10:56 daconpi volumio[1245]: info: MPD Permissions set Aug 27 19:10:56 daconpi volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Aug 27 19:10:56 daconpi volumio[1245]: info: Completed starting Core Plugins Aug 27 19:10:56 daconpi volumio[1245]: info: ------------------------------------------- Aug 27 19:10:56 daconpi volumio[1245]: info: ----- MyVolumio plugins startup ---- Aug 27 19:10:56 daconpi volumio[1245]: info: ------------------------------------------- Aug 27 19:10:56 daconpi volumio[1245]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 27 19:10:56 daconpi volumio[1245]: info: Spotify config file written Aug 27 19:10:56 daconpi volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Aug 27 19:10:56 daconpi volumio[1245]: info: Received Get System Info Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:10:56 daconpi volumio[1245]: info: Discovery: Getting this device information Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:56 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:10:56 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:56.777-07:00 level=INFO msg="system info for c51b3c3cb536488e32667ac3229eb756" deviceName=DacOnPi deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 27 19:10:56 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:56.790-07:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 27 19:10:56 daconpi volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:56 daconpi sudo[1638]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 27 19:10:56 daconpi sudo[1638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:56 daconpi systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 27 19:10:56 daconpi systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 27 19:10:56 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:10:57 daconpi go-librespot[1650]: go-librespot daemon starting... Aug 27 19:10:57 daconpi sudo[1638]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:57 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:10:57 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:10:57 daconpi volumio[1245]: info: No need to fix Spotify hosts Aug 27 19:10:57 daconpi volumio[1245]: info: Received Get System Info Aug 27 19:10:57 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:10:57 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:10:57 daconpi volumio[1245]: info: Discovery: Getting this device information Aug 27 19:10:57 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:57 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:57 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:10:57 daconpi volumio[1245]: error: MPD error: The expression evaluated to a falsy value: Aug 27 19:10:57 daconpi volumio[1245]: assert.ok(self.idling) Aug 27 19:10:57 daconpi volumio[1245]: error: The expression evaluated to a falsy value: Aug 27 19:10:57 daconpi volumio[1245]: assert.ok(self.idling) Aug 27 19:10:57 daconpi volumio[1245]: info: MPD running with PID1578 Aug 27 19:10:57 daconpi volumio[1245]: ,establishing connection Aug 27 19:10:57 daconpi volumio[1245]: info: Volumio called home Aug 27 19:10:57 daconpi volumio-remote-updater[836]: Test mode disabled Aug 27 19:10:57 daconpi volumio-remote-updater[836]: Alpha mode disabled Aug 27 19:10:57 daconpi volumio-remote-updater[836]: Alpha legacy test mode disabled Aug 27 19:10:57 daconpi volumio[1245]: error: updateQueue error: null Aug 27 19:10:57 daconpi go-librespot[1651]: time="2026-08-27T19:10:57-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:10:57 daconpi go-librespot[1651]: time="2026-08-27T19:10:57-07:00" level=debug msg="app state loaded" Aug 27 19:10:57 daconpi volumio[1245]: info: New Spotify access tokenBQAdpRvPQ1... Aug 27 19:10:57 daconpi volumio[1245]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 27 19:10:57 daconpi volumio[1245]: info: Starting Shairport Sync Aug 27 19:10:57 daconpi go-librespot[1651]: time="2026-08-27T19:10:57-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:10:57 daconpi volumio[1245]: info: Starting Shairport Sync Aug 27 19:10:57 daconpi volumio[1245]: info: Starting Shairport Sync Aug 27 19:10:57 daconpi volumio[1245]: error: updateQueue error: null Aug 27 19:10:57 daconpi sudo[1661]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 27 19:10:57 daconpi sudo[1661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:57 daconpi sudo[1664]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 27 19:10:57 daconpi sudo[1664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:57 daconpi sudo[1665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 27 19:10:57 daconpi sudo[1665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:57 daconpi sudo[1670]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 27 19:10:57 daconpi sudo[1670]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 27 19:10:58 daconpi systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=info msg="zeroconf server listening on port 36657" Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:10:58 daconpi systemd[1]: shairport-sync.service: Deactivated successfully. Aug 27 19:10:58 daconpi systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:10:58 daconpi systemd[1]: shairport-sync.service: Consumed 1.189s CPU time. Aug 27 19:10:58 daconpi volumio[1245]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 27 19:10:58 daconpi systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:10:58 daconpi systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 27 19:10:58 daconpi systemd[1]: shairport-sync.service: Deactivated successfully. Aug 27 19:10:58 daconpi systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=debug msg="obtained new client token: AAF7tIwwslAUBaUVKzA9FNK0hHhdlUezvEl5GkAFiexOHIaABdjkM6OgLlxdOop8f4xzQhVmmK6cvXSGBAnTPvIyzVp/NL7zHhZUcRoanf2FGIx9NmoG7YmCnUWy+3TX/Wh0kza5HgpizS0ykpbiKPHudL8H917K93l7pMSPAZX75Tl71sa0wVerIexOnY04TMjp+Di8ArnlPEDJOMa5bm9f95rkTiq0gH7K71YswLDyJBgmfduLVg==" Aug 27 19:10:58 daconpi systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:10:58 daconpi sudo[1661]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:58 daconpi sudo[1665]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:58 daconpi systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 27 19:10:58 daconpi systemd[1]: shairport-sync.service: Deactivated successfully. Aug 27 19:10:58 daconpi systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:10:58 daconpi systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:10:58 daconpi sudo[1664]: pam_unix(sudo:session): session closed for user root Aug 27 19:10:58 daconpi ntpd[1061]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Aug 27 19:10:58 daconpi ntpd[1061]: DNS: Pool taking: 54.39.104.183 Aug 27 19:10:58 daconpi ntpd[1061]: DNS: Pool taking: 167.160.187.179 Aug 27 19:10:58 daconpi ntpd[1061]: DNS: Pool taking: 173.33.196.30 Aug 27 19:10:58 daconpi ntpd[1061]: DNS: Pool taking: 23.159.16.194 Aug 27 19:10:58 daconpi ntpd[1061]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 19:10:58 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:58.448-07:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Aug 27 19:10:58 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:58.449-07:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Aug 27 19:10:58 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:58.449-07: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 27 19:10:58 daconpi volumio[1245]: info: Shairport-Sync Started Aug 27 19:10:58 daconpi volumio[1245]: Error adding Membership: Error: addMembership EINVAL Aug 27 19:10:58 daconpi volumio[1245]: info: Shairport-Sync Started Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=debug msg="completed keyexchange" Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=debug msg="completed challenge" Aug 27 19:10:58 daconpi volumio[1245]: info: Shairport-Sync Started Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 19:10:58 daconpi volumio[1245]: info: Received Get System Info Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:10:58 daconpi volumio[1245]: info: Discovery: Getting this device information Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:58 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:58 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 27 19:10:58 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 27 19:10:58 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:58.808-07:00 level=INFO msg="enabling local network discovery" Aug 27 19:10:58 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:58.824-07:00 level=INFO msg="enabling BLE discovery" Aug 27 19:10:58 daconpi bluealsa[970]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_73_43_F9_7C_E1_7E, ...) Aug 27 19:10:58 daconpi go-librespot[1651]: time="2026-08-27T19:10:58-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:10:58 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:10:58 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 27 19:10:59 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:59.058-07:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.200:59425 Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:10:59 daconpi volumio[1245]: info: Discovery: Getting this device information Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:59 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:10:59 daconpi volumio[1245]: verbose: New Socket.io Connection to 192.168.0.65:3000 from 192.168.0.200 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 27 19:10:59 daconpi volumio[1245]: SPOTIFY: User informations: {"account_id":"fr38g8u8Pg","country":"CA","display_name":"12171800659","email":"nut10992@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/12171800659"},"followers":{"href":null,"total":6},"href":"https://api.spotify.com/v1/users/12171800659","id":"12171800659","images":[],"product":"premium","type":"user","uri":"spotify:user:12171800659"} Aug 27 19:10:59 daconpi volumio[1245]: info: Spotify Successfully logged in Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 19:10:59 daconpi volumio[1245]: info: [1787883059584] CoreMusicLibrary::Adding element Spotify Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:10:59 daconpi volumio[1245]: Cannot find translation for source Spotify Aug 27 19:10:59 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:10:59.805-07:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 27 19:10:59 daconpi volumio[1245]: verbose: New Socket.io Connection to 192.168.0.65:3000 from 192.168.0.200 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:10:59 daconpi volumio[1245]: info: Discovery: Getting this device information Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:10:59 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:10:59 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:11:00 daconpi volumio[1245]: verbose: New Socket.io Connection to 192.168.0.65:3000 from 192.168.0.200 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:11:00 daconpi volumio[1245]: info: Discovery: Getting this device information Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:11:00 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.256-07:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.365-07:00 level=INFO msg="new address was allocated" component=ble/conn old=2 new=3 Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.433-07:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.200:59636 Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.463-07:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.0.200:59636 Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.463-07:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.0.200:59636 Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.472-07:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.200:59638 Aug 27 19:11:00 daconpi volumio[1245]: info: go-librespot daemon successfully initialized Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.488-07:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.0.200:59638 @ 0x237adb0" latency=5.752431ms timeout=20s Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.488-07:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.489-07:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.0.200:59638 @ 0x237adb0" latency=6.45236ms platform=PLATFORM_IOS version=6.260807.0 Aug 27 19:11:00 daconpi volumio[1245]: info: Received Get System Info Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:11:00 daconpi volumio[1245]: info: Discovery: Getting this device information Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:11:00 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.505-07:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" name=DacOnPi Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.508-07:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" language=en Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.511-07:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" timezone=America/Vancouver Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.512-07:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" available=true connected=false macAddress= ip4Address= ip6Address= Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.516-07:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" available=true connected=true macAddress=dc:a6:32:62:1f:28 ip4Address=192.168.0.65/24 ip6Address= ssid=Banana-Ji_5G Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.516-07:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" setupComplete=true Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:00 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 27 19:11:00 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:00.576-07:00 level=INFO msg="new address was allocated" component=ble/conn old=3 new=4 Aug 27 19:11:00 daconpi volumio[1245]: amixer -c 0 info | grep "bcm2835 ALSA" Aug 27 19:11:00 daconpi volumio[1245]: amixer -c 1 info | grep "bcm2835 Headphones" Aug 27 19:11:00 daconpi dbus-daemon[806]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.20" (uid=0 pid=1555 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.2" (uid=0 pid=805 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 27 19:11:00 daconpi volumio[1245]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' Aug 27 19:11:00 daconpi volumio[1245]: amixer -c 2 info | grep "vc4-hdmi-0" Aug 27 19:11:00 daconpi volumio[1245]: Card sysdefault:2 'vc4hdmi0'/'vc4-hdmi-0' Aug 27 19:11:00 daconpi volumio[1245]: amixer -c 3 info | grep "vc4-hdmi-1" Aug 27 19:11:00 daconpi volumio[1245]: Card sysdefault:3 'vc4hdmi1'/'vc4-hdmi-1' Aug 27 19:11:00 daconpi volumio[1245]: amixer -c 4 info | grep "BossDAC" Aug 27 19:11:00 daconpi volumio[1245]: Card sysdefault:4 'BossDAC'/'BossDAC' Aug 27 19:11:00 daconpi volumio[1245]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 4 Aug 27 19:11:00 daconpi volumio[1245]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 27 19:11:00 daconpi volumio[1245]: {"cmd":"/usr/local/bin/alsacap -C 4","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 4\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 27 19:11:00 daconpi volumio[1245]: amixer -c 4 info | grep "Innomaker Dac" Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.061-07:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" selectedOutputId=4 Aug 27 19:11:01 daconpi volumio[1245]: info: Received Get System Info Aug 27 19:11:01 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:11:01 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:11:01 daconpi volumio[1245]: info: Discovery: Getting this device information Aug 27 19:11:01 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:11:01 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:11:01 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.076-07:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" currentVersion=4.119 latestVersion=4.119 Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.077-07:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.0.200:59638 @ 0x237adb0" status=UPDATE_STATUS_NONE progress=0 Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.077-07:00 level=INFO msg="emitting user changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" userId= Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.077-07:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" providers=3 Aug 27 19:11:01 daconpi dbus-daemon[806]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.20" (uid=0 pid=1555 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.2" (uid=0 pid=805 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 27 19:11:01 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.136-07:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" plugins=0 Aug 27 19:11:01 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:11:01 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.155-07:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" state=STATUS_STOPPED positionMs=0 volume=33 Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.156-07:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:59638 @ 0x237adb0" id= title= Aug 27 19:11:01 daconpi kernel: Bluetooth: hci0: Opcode 0x200a failed: -16 Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.234-07:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.855085ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.277-07:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.664-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://securetoken.googleapis.com duration=384.482545ms Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.694-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://www.googleapis.com duration=415.44167ms Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.740-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://google.com duration=462.617487ms Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.895-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=617.165143ms Aug 27 19:11:01 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:01.975-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=http://pushupdates.volumio.org duration=696.897987ms Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.074-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://functions.volumio.cloud duration=794.947565ms Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.074-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://functions.volumio.cloud duration=795.710325ms Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.074-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=797.303432ms Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.074-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://database.volumio.cloud duration=795.371166ms Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.090-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=812.467438ms Aug 27 19:11:02 daconpi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 27 19:11:02 daconpi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.132-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=851.974433ms Aug 27 19:11:02 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:02 daconpi go-librespot[1748]: go-librespot daemon starting... Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=debug msg="app state loaded" Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:11:02 daconpi volumio[1245]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.408-07:00 level=INFO msg="new address was allocated" component=ble/conn old=4 new=5 Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.453-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=http://plugins.volumio.org duration=1.174214859s Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=info msg="zeroconf server listening on port 38103" Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:11:02 daconpi sudo[1760]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 27 19:11:02 daconpi sudo[1760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:11:02 daconpi dbus-daemon[806]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.20" (uid=0 pid=1555 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.2" (uid=0 pid=805 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=debug msg="obtained new client token: AAFfPxnn3/EgRcyegQW2HHvpQwansP8ly1R7kLIxUB2CutT2NqQ2KrygtZlGuhYJQPSQL7WF7Cn1+DK404jH1H34DWZG8MfE0jcES1GmxRZjINUPmlFlms/G00+qPDqSn/z/XVEoPR5SqEk/2Qi730FKX7N7P6Lcjx8yIs6aUYln73EtywLGU/fiJTyih1mWQccl//M+mtK2DfBzcO6JAroi1xmKuOrGe0UPKpa39cFm9oPoYjIqDZ4H" Aug 27 19:11:02 daconpi sudo[1761]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 27 19:11:02 daconpi sudo[1761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:11:02 daconpi sudo[1760]: pam_unix(sudo:session): session closed for user root Aug 27 19:11:02 daconpi sudo[1761]: pam_unix(sudo:session): session closed for user root Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 27 19:11:02 daconpi volumio[1245]: verbose: New Socket.io Connection to 192.168.0.65 from 192.168.0.200 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: 4 Aug 27 19:11:02 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:02.722-07:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:59638,00:00:00:00:00:00%02 @ 0x237adb0" latency=12.228462ms timeout=10s endpoint=http://cddb.volumio.org duration=1.44388783s Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=debug msg="completed keyexchange" Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=debug msg="completed challenge" Aug 27 19:11:02 daconpi go-librespot[1749]: time="2026-08-27T19:11:02-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:11:03 daconpi go-librespot[1749]: time="2026-08-27T19:11:03-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:11:03 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:11:03 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 27 19:11:03 daconpi systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Aug 27 19:11:03 daconpi systemd[1]: e2scrub_all.service: Deactivated successfully. Aug 27 19:11:03 daconpi systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Aug 27 19:11:03 daconpi sudo[1766]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 27 19:11:03 daconpi sudo[1766]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:11:03 daconpi sudo[1766]: pam_unix(sudo:session): session closed for user root Aug 27 19:11:03 daconpi sudo[1769]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 27 19:11:03 daconpi sudo[1769]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:11:03 daconpi volumio[1245]: info: Initializing connection to go-librespot Websocket Aug 27 19:11:03 daconpi sudo[1769]: pam_unix(sudo:session): session closed for user root Aug 27 19:11:03 daconpi volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 27 19:11:03 daconpi volumio[1245]: verbose: New Socket.io Connection to 192.168.0.65 from 192.168.0.200 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: 4 Aug 27 19:11:03 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:11:03 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:11:03 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 27 19:11:03 daconpi volumio[1245]: info: Listing playlists Aug 27 19:11:03 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 27 19:11:03 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 27 19:11:03 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 27 19:11:03 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 27 19:11:04 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:04.400-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 27 19:11:04 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 27 19:11:05 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 27 19:11:05 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 27 19:11:05 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 27 19:11:05 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 27 19:11:05 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 27 19:11:05 daconpi volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 27 19:11:05 daconpi volumio[1245]: info: Adding plugin bluetooth to MyMusic Plugins Aug 27 19:11:05 daconpi volumio[1245]: info: Adding plugin multiroom to MyMusic Plugins Aug 27 19:11:05 daconpi volumio[1245]: info: Adding plugin metavolumio to MyMusic Plugins Aug 27 19:11:05 daconpi volumio[1245]: info: Adding plugin cd_controller to MyMusic Plugins Aug 27 19:11:05 daconpi volumio[1245]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 27 19:11:05 daconpi volumio[1245]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 27 19:11:05 daconpi volumio[1245]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 27 19:11:05 daconpi volumio[1245]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 27 19:11:06 daconpi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 27 19:11:06 daconpi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:06 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:06 daconpi go-librespot[1785]: go-librespot daemon starting... Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=debug msg="app state loaded" Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=info msg="zeroconf server listening on port 38249" Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:11:06 daconpi go-librespot[1786]: time="2026-08-27T19:11:06-07:00" level=debug msg="obtained new client token: AAHrToBp7ekDNW3NLQ4ebKSz54dZAjL0gbNM3kp9g/V0FiYjg/3ZhYNtz2xLIzk4B6JhvjJ3/mJAjCHXd7MUWHMNOoolaJkVqdxNlwp2PQ+wTcaSzHcSCycCORUSx9Wu4TeyejC3Rqiwdfq9hyVhTVJ75cW5msDze56P5cta1dvlWfFjcZhT4aT1zzWNF4x7QofEUAOrLUrZzaiY+DctsMJde+ji4n6DSH2dk2sZmMkvUbPtMpnHn8Fu" Aug 27 19:11:06 daconpi systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 27 19:11:07 daconpi go-librespot[1786]: time="2026-08-27T19:11:07-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 27 19:11:07 daconpi go-librespot[1786]: time="2026-08-27T19:11:07-07:00" level=debug msg="completed keyexchange" Aug 27 19:11:07 daconpi go-librespot[1786]: time="2026-08-27T19:11:07-07:00" level=debug msg="completed challenge" Aug 27 19:11:07 daconpi go-librespot[1786]: time="2026-08-27T19:11:07-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:11:07 daconpi go-librespot[1786]: time="2026-08-27T19:11:07-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:11:07 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:11:07 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 27 19:11:07 daconpi kernel: ------------[ cut here ]------------ Aug 27 19:11:07 daconpi kernel: WARNING: CPU: 0 PID: 220 at drivers/gpu/drm/vc4/vc4_hvs.c:1064 __vc4_hvs_stop_channel+0x168/0x1dc [vc4] Aug 27 19:11:07 daconpi kernel: Modules linked in: cmac algif_hash aes_arm_bs crypto_simd cryptd aes_arm aes_generic algif_skcipher af_alg nft_chain_nat bnep xt_REDIRECT nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink 8021q garp stp llc bcm2835_codec(C) binfmt_misc brcmfmac_wcc bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) snd_soc_pcm512x_i2c rpi_hevc_dec brcmfmac hci_uart btbcm videobuf2_vmalloc snd_soc_pcm512x vc_sm_cma(C) v4l2_mem2mem brcmutil videobuf2_dma_contig regmap_i2c cfg80211 bluetooth videobuf2_memops videobuf2_v4l2 videodev snd_soc_allo_boss_dac raspberrypi_hwmon videobuf2_common ecdh_generic ecc rfkill libaes raspberrypi_gpiomem mc nvmem_rmem uio_pdrv_genirq uio i2c_dev dm_mod ip_tables x_tables ipv6 ads7846 fb_hx8357d(C) fb_st7789v(C) fb_st7735r(C) fb_ili9341(C) fb_ili9340(C) fbtft(C) panel_waveshare_dsi_v2 panel_waveshare_dsi panel_ilitek_ili9881c panel_raspberrypi_touchscreen pwm_bcm2835 spi_bcm2835 squashfs overlay nls_iso8859_1 fuse vc4 snd_soc_hdmi_codec Aug 27 19:11:07 daconpi kernel: drm_display_helper cec drm_dma_helper snd_soc_bcm2835_i2s snd_soc_core snd_compress v3d gpu_sched drm_shmem_helper drm_kms_helper snd_bcm2835(C) snd_pcm_dmaengine drm snd_pcm drm_panel_orientation_quirks snd_timer i2c_brcmstb i2c_bcm2835 snd backlight clk_hifiberry_dacpro Aug 27 19:11:07 daconpi kernel: CPU: 0 UID: 0 PID: 220 Comm: irq/60-vc4 hdmi Tainted: G C 6.12.74-v7l+ #1948 Aug 27 19:11:07 daconpi kernel: Tainted: [C]=CRAP Aug 27 19:11:07 daconpi kernel: Hardware name: BCM2711 Aug 27 19:11:07 daconpi kernel: Call trace: Aug 27 19:11:07 daconpi kernel: unwind_backtrace from show_stack+0x18/0x1c Aug 27 19:11:07 daconpi kernel: show_stack from dump_stack_lvl+0x5c/0x80 Aug 27 19:11:07 daconpi kernel: dump_stack_lvl from __warn+0x88/0x124 Aug 27 19:11:07 daconpi kernel: __warn from warn_slowpath_fmt+0x184/0x190 Aug 27 19:11:07 daconpi kernel: warn_slowpath_fmt from __vc4_hvs_stop_channel+0x168/0x1dc [vc4] Aug 27 19:11:07 daconpi kernel: __vc4_hvs_stop_channel [vc4] from vc4_crtc_disable+0x138/0x1dc [vc4] Aug 27 19:11:07 daconpi kernel: vc4_crtc_disable [vc4] from vc4_crtc_atomic_disable+0x9c/0xc0 [vc4] Aug 27 19:11:07 daconpi kernel: vc4_crtc_atomic_disable [vc4] from disable_outputs+0x268/0x3a0 [drm_kms_helper] Aug 27 19:11:07 daconpi kernel: disable_outputs [drm_kms_helper] from drm_atomic_helper_commit_modeset_disables+0x18/0x3c [drm_kms_helper] Aug 27 19:11:07 daconpi kernel: drm_atomic_helper_commit_modeset_disables [drm_kms_helper] from vc4_atomic_commit_tail+0x194/0x998 [vc4] Aug 27 19:11:07 daconpi kernel: vc4_atomic_commit_tail [vc4] from commit_tail+0xa4/0x18c [drm_kms_helper] Aug 27 19:11:07 daconpi kernel: commit_tail [drm_kms_helper] from drm_atomic_helper_commit+0x140/0x164 [drm_kms_helper] Aug 27 19:11:07 daconpi kernel: drm_atomic_helper_commit [drm_kms_helper] from drm_atomic_commit+0xc8/0x100 [drm] Aug 27 19:11:07 daconpi kernel: drm_atomic_commit [drm] from drm_client_modeset_commit_atomic+0x1f8/0x230 [drm] Aug 27 19:11:07 daconpi kernel: drm_client_modeset_commit_atomic [drm] from drm_client_modeset_commit_locked+0x64/0x18c [drm] Aug 27 19:11:07 daconpi kernel: drm_client_modeset_commit_locked [drm] from drm_client_modeset_commit+0x2c/0x48 [drm] Aug 27 19:11:07 daconpi kernel: drm_client_modeset_commit [drm] from __drm_fb_helper_restore_fbdev_mode_unlocked+0x9c/0xc4 [drm_kms_helper] Aug 27 19:11:07 daconpi kernel: __drm_fb_helper_restore_fbdev_mode_unlocked [drm_kms_helper] from drm_fb_helper_hotplug_event+0xf8/0x10c [drm_kms_helper] Aug 27 19:11:07 daconpi kernel: drm_fb_helper_hotplug_event [drm_kms_helper] from drm_client_dev_hotplug+0xbc/0x114 [drm] Aug 27 19:11:07 daconpi kernel: drm_client_dev_hotplug [drm] from drm_connector_helper_hpd_irq_event+0x60/0x9c [drm_kms_helper] Aug 27 19:11:07 daconpi kernel: drm_connector_helper_hpd_irq_event [drm_kms_helper] from vc4_hdmi_hpd_irq_thread+0x48/0x50 [vc4] Aug 27 19:11:07 daconpi kernel: vc4_hdmi_hpd_irq_thread [vc4] from irq_thread_fn+0x24/0x84 Aug 27 19:11:07 daconpi kernel: irq_thread_fn from irq_thread+0x13c/0x22c Aug 27 19:11:07 daconpi kernel: irq_thread from kthread+0xe8/0x104 Aug 27 19:11:07 daconpi kernel: kthread from ret_from_fork+0x14/0x38 Aug 27 19:11:07 daconpi kernel: Exception stack(0xf09b1fb0 to 0xf09b1ff8) Aug 27 19:11:07 daconpi kernel: 1fa0: 00000000 00000000 00000000 00000000 Aug 27 19:11:07 daconpi kernel: 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 Aug 27 19:11:07 daconpi kernel: 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000 Aug 27 19:11:07 daconpi kernel: ---[ end trace 0000000000000000 ]--- Aug 27 19:11:07 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:07.709-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:09 daconpi volumio[1245]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 27 19:11:09 daconpi volumio[1245]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 27 19:11:09 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:09 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:09 daconpi volumio[1245]: info: Starting MyVolumio Remote Streaming Endpoints Aug 27 19:11:10 daconpi volumio[1245]: info: MyVolumio login type: Token Aug 27 19:11:10 daconpi volumio[1245]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 27 19:11:10 daconpi volumio[1245]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 27 19:11:10 daconpi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 27 19:11:10 daconpi systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 27 19:11:10 daconpi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:10 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:10 daconpi go-librespot[1814]: go-librespot daemon starting... Aug 27 19:11:10 daconpi systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:11:10 daconpi systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:11:10 daconpi go-librespot[1815]: time="2026-08-27T19:11:10-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:11:10 daconpi go-librespot[1815]: time="2026-08-27T19:11:10-07:00" level=debug msg="app state loaded" Aug 27 19:11:10 daconpi sudo[1670]: pam_unix(sudo:session): session closed for user root Aug 27 19:11:10 daconpi go-librespot[1815]: time="2026-08-27T19:11:10-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:11:10 daconpi go-librespot[1815]: time="2026-08-27T19:11:10-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 27 19:11:10 daconpi go-librespot[1815]: time="2026-08-27T19:11:10-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 27 19:11:10 daconpi go-librespot[1815]: time="2026-08-27T19:11:10-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 27 19:11:10 daconpi go-librespot[1815]: time="2026-08-27T19:11:10-07:00" level=info msg="zeroconf server listening on port 34695" Aug 27 19:11:10 daconpi go-librespot[1815]: time="2026-08-27T19:11:10-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:11:11 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:11.015-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:11 daconpi go-librespot[1815]: time="2026-08-27T19:11:11-07:00" level=debug msg="obtained new client token: AAFmRLEw1T7zFQ+OF3GgW21Q3vjl6lvqCW2az8uEnv/YdJ/wgR8Nl9rpGaOtiPQ5p1WUhZkWebOwaKx0TlJItO6xwLxHDYdY7dFiK7/iTpvrQHbrsV3TOPt8gy5z2Ux9D+1FEAq/4tiYt09iuSUzvSj5MLaGQG4qAbscI1G1lOL8fkyFjWpJJzbl0XiFX28wbYMuyFywjQR5fkNN4kRBiBkBpeqNI5VkpZF8BSOddkY5Ob4HPYa4GQ==" Aug 27 19:11:11 daconpi go-librespot[1815]: time="2026-08-27T19:11:11-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 27 19:11:11 daconpi go-librespot[1815]: time="2026-08-27T19:11:11-07:00" level=debug msg="completed keyexchange" Aug 27 19:11:11 daconpi go-librespot[1815]: time="2026-08-27T19:11:11-07:00" level=debug msg="completed challenge" Aug 27 19:11:11 daconpi go-librespot[1815]: time="2026-08-27T19:11:11-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:11:11 daconpi go-librespot[1815]: time="2026-08-27T19:11:11-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:11:11 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:11:11 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 27 19:11:13 daconpi volumio[1245]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 27 19:11:13 daconpi volumio[1245]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 27 19:11:13 daconpi volumio[1245]: info: Streaming services startup Aug 27 19:11:13 daconpi volumio[1245]: info: Starting Streaming Daemon Aug 27 19:11:13 daconpi volumio[1245]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 27 19:11:13 daconpi sudo[1836]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 27 19:11:13 daconpi sudo[1836]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:11:13 daconpi sudo[1836]: pam_unix(sudo:session): session closed for user root Aug 27 19:11:13 daconpi volumio[1245]: info: Initializing connection to go-librespot Websocket Aug 27 19:11:13 daconpi volumio[1245]: error: Cannot start Volumio Streaming Daemon Aug 27 19:11:13 daconpi volumio[1245]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 27 19:11:13 daconpi volumio[1245]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 27 19:11:13 daconpi volumio[1245]: info: Upmpdcli Daemon Started Aug 27 19:11:13 daconpi volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 27 19:11:14 daconpi volumio[1245]: error: MyVolumio Custom Token format not valid, refreshing it Aug 27 19:11:14 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:14.332-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:14 daconpi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 27 19:11:14 daconpi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:14 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:14 daconpi go-librespot[1850]: go-librespot daemon starting... Aug 27 19:11:14 daconpi go-librespot[1853]: time="2026-08-27T19:11:14-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:11:14 daconpi go-librespot[1853]: time="2026-08-27T19:11:14-07:00" level=debug msg="app state loaded" Aug 27 19:11:14 daconpi volumio[1245]: info: MyVolumio login type: Token Aug 27 19:11:14 daconpi go-librespot[1853]: time="2026-08-27T19:11:14-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:11:15 daconpi systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 27 19:11:15 daconpi systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=info msg="zeroconf server listening on port 37423" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=debug msg="obtained new client token: AAFOCtthPFzoxattMqdooFhPss7Zv6AjLl7tMLS0DrmCYOYYabs4Lxn2hpduci7ZOer3PhDdoIDUvhNb0P5qoEdvNgt+fJh3IHuAPQmmtmPk7HAr+RDt332fvyxhPQuE9jhA32I5m4ZvDRTvqese5MILfyHwjthfqKC0VwlhQYujHu28WGSOgn1WuyEuTrxgxygEwJQl4RDKNHevhYjAEAlVL4EUrLvvcqIrbrrYRfivpqL/JYAt2wfW" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=debug msg="connected to ap-guc3.spotify.com:443" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=debug msg="completed keyexchange" Aug 27 19:11:15 daconpi go-librespot[1853]: time="2026-08-27T19:11:15-07:00" level=debug msg="completed challenge" Aug 27 19:11:16 daconpi volumio[1245]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 27 19:11:16 daconpi go-librespot[1853]: time="2026-08-27T19:11:16-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:11:16 daconpi go-librespot[1853]: time="2026-08-27T19:11:16-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:11:16 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:11:16 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 27 19:11:16 daconpi volumio[1245]: info: MyVolumio token set successfully Aug 27 19:11:16 daconpi volumio[1245]: info: MYVOLUMIO: Adding device Aug 27 19:11:16 daconpi volumio[1245]: info: MYVOLUMIO: Evaluating Server Aug 27 19:11:17 daconpi volumio[1245]: info: MyVolumio status changed Aug 27 19:11:17 daconpi volumio[1245]: info: Streaming services startup Aug 27 19:11:17 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:17.652-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:17 daconpi volumio[1245]: info: Starting Streaming Daemon Aug 27 19:11:17 daconpi volumio[1245]: info: Removing browser output: myVolumio user plan is not superstar Aug 27 19:11:17 daconpi volumio[1245]: info: Removing audio output: Aug 27 19:11:17 daconpi volumio[1245]: info: Stoppping Tunnel 1 Aug 27 19:11:17 daconpi volumio[1245]: info: Initializing connection to go-librespot Websocket Aug 27 19:11:17 daconpi sudo[1903]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 27 19:11:17 daconpi sudo[1903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:11:17 daconpi sudo[1905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 27 19:11:17 daconpi sudo[1905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:11:17 daconpi sudo[1903]: pam_unix(sudo:session): session closed for user root Aug 27 19:11:17 daconpi 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 27 19:11:17 daconpi 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 27 19:11:17 daconpi 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 27 19:11:17 daconpi 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 27 19:11:17 daconpi volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 27 19:11:17 daconpi volumio[1245]: error: Cannot start Volumio Streaming Daemon Aug 27 19:11:17 daconpi volumio[1245]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 27 19:11:17 daconpi volumio[1245]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 27 19:11:17 daconpi 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 27 19:11:17 daconpi 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 27 19:11:17 daconpi sudo[1905]: pam_unix(sudo:session): session closed for user root Aug 27 19:11:17 daconpi volumio[1245]: info: Remote SSH Stopped Aug 27 19:11:18 daconpi volumio[1245]: info: Setting Geolocation for MyVolumio to eu8 Aug 27 19:11:18 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:18 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:18 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:18 daconpi volumio[1245]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Aug 27 19:11:19 daconpi volumio[1245]: info: Updating MyVolumio device info Aug 27 19:11:19 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:19 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:19 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:19 daconpi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 27 19:11:19 daconpi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:19 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:19 daconpi go-librespot[1908]: go-librespot daemon starting... Aug 27 19:11:19 daconpi volumio[1245]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=debug msg="app state loaded" Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=info msg="zeroconf server listening on port 40457" Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:11:19 daconpi go-librespot[1909]: time="2026-08-27T19:11:19-07:00" level=debug msg="obtained new client token: AAH6fqh9rGkCPl6TNGltX3ZMHcaDIFz8hne4MyC4C6bR6yjYcBbMfOfwHfClb236F3Rm5sK0LXcGwTiAdxQEQD9F05KZtDqGsvdyNqmu5yKUTd7F8nksAR0/zoVW+DaXjTaoNtMTOFGIziKOHPUflRB/mwCBeF422FwHd1uYlrFsTzU6xxUN0d0r+PaEbJKXoT5rmNLiIcZyKBiWIBIfTWQWu0qRPZjtxR+8hqlLUuHXc6rU2JhnQymj" Aug 27 19:11:20 daconpi go-librespot[1909]: time="2026-08-27T19:11:20-07:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Aug 27 19:11:20 daconpi go-librespot[1909]: time="2026-08-27T19:11:20-07:00" level=debug msg="connected to ap-guc3.spotify.com:443" Aug 27 19:11:20 daconpi go-librespot[1909]: time="2026-08-27T19:11:20-07:00" level=debug msg="completed keyexchange" Aug 27 19:11:20 daconpi go-librespot[1909]: time="2026-08-27T19:11:20-07:00" level=debug msg="completed challenge" Aug 27 19:11:20 daconpi go-librespot[1909]: time="2026-08-27T19:11:20-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:11:20 daconpi go-librespot[1909]: time="2026-08-27T19:11:20-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:11:20 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:11:20 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 27 19:11:20 daconpi volumio[1245]: info: Initializing connection to go-librespot Websocket Aug 27 19:11:20 daconpi volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 27 19:11:20 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:20.959-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:22 daconpi volumio[1245]: info: MYVOLUMIO: Adding device Aug 27 19:11:22 daconpi volumio[1245]: info: MYVOLUMIO: Evaluating Server Aug 27 19:11:23 daconpi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 27 19:11:23 daconpi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:23 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:23 daconpi go-librespot[1929]: go-librespot daemon starting... Aug 27 19:11:23 daconpi go-librespot[1931]: time="2026-08-27T19:11:23-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:11:23 daconpi go-librespot[1931]: time="2026-08-27T19:11:23-07:00" level=debug msg="app state loaded" Aug 27 19:11:23 daconpi go-librespot[1931]: time="2026-08-27T19:11:23-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:11:23 daconpi go-librespot[1931]: time="2026-08-27T19:11:23-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 27 19:11:23 daconpi go-librespot[1931]: time="2026-08-27T19:11:23-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 27 19:11:23 daconpi go-librespot[1931]: time="2026-08-27T19:11:23-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 27 19:11:23 daconpi go-librespot[1931]: time="2026-08-27T19:11:23-07:00" level=info msg="zeroconf server listening on port 37057" Aug 27 19:11:24 daconpi go-librespot[1931]: time="2026-08-27T19:11:24-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:11:24 daconpi volumio[1245]: info: Initializing connection to go-librespot Websocket Aug 27 19:11:24 daconpi go-librespot[1931]: time="2026-08-27T19:11:24-07:00" level=debug msg="obtained new client token: AAFmMbOtBOW0WC0OlsbV5Lh/ti1fE+W0y3+sqpmmQ/hFzv3HFNZuZRz+noioJ9BONK10NOhv2/uExmrl5MdMh7wAKTLjj5xgu3pYUI5chVTmWGLM0Uw9p/ZUVmrYcy65nrxZ5qIUW8/1ezfPQ2NxZT0fxGU5FORPr5lSaCGtK3NchyNpjiL7ydp+6azcBGQdxfcCpakztxQD0rLOotmdIPcM9sb7j+JkYM0SYBL9BiyLyN2XOmIr1w==" Aug 27 19:11:24 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:24.267-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:24 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 19:11:24 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:24 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 27 19:11:24 daconpi go-librespot[1931]: time="2026-08-27T19:11:24-07:00" level=debug msg="new websocket client" Aug 27 19:11:24 daconpi volumio[1245]: info: Connection to go-librespot Websocket established Aug 27 19:11:24 daconpi go-librespot[1931]: time="2026-08-27T19:11:24-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 27 19:11:24 daconpi volumio-remote-updater[836]: Test mode disabled Aug 27 19:11:24 daconpi volumio-remote-updater[836]: Alpha mode disabled Aug 27 19:11:24 daconpi volumio-remote-updater[836]: Alpha legacy test mode disabled Aug 27 19:11:24 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 27 19:11:24 daconpi volumio[1245]: info: Setting Geolocation for MyVolumio to us4 Aug 27 19:11:24 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:24 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:24 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:24 daconpi go-librespot[1931]: time="2026-08-27T19:11:24-07:00" level=debug msg="completed keyexchange" Aug 27 19:11:24 daconpi go-librespot[1931]: time="2026-08-27T19:11:24-07:00" level=debug msg="completed challenge" Aug 27 19:11:24 daconpi go-librespot[1931]: time="2026-08-27T19:11:24-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:11:24 daconpi go-librespot[1931]: time="2026-08-27T19:11:24-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:11:24 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:11:24 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 27 19:11:24 daconpi volumio[1245]: info: Connection to go-librespot Websocket closed Aug 27 19:11:24 daconpi volumio[1245]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 27 19:11:24 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 27 19:11:25 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 27 19:11:25 daconpi volumio[1245]: 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 27 19:11:25 daconpi volumio[1245]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Aug 27 19:11:25 daconpi volumio[1245]: info: CoreCommandRouter::volumioGetState Aug 27 19:11:25 daconpi volumio[1245]: info: CorePlayQueue::getTrack 0 Aug 27 19:11:25 daconpi volumio[1245]: info: Updating MyVolumio device info Aug 27 19:11:25 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:25 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:25 daconpi volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:11:26 daconpi volumio[1245]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Aug 27 19:11:27 daconpi volumio[1245]: info: Getting Spotify volume Aug 27 19:11:27 daconpi volumio[1245]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 19:11:27 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:27.577-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:27 daconpi volumio[1245]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 27 19:11:27 daconpi volumio[1245]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 27 19:11:27 daconpi volumio[1245]: errno: -111, Aug 27 19:11:27 daconpi volumio[1245]: code: 'ECONNREFUSED', Aug 27 19:11:27 daconpi volumio[1245]: syscall: 'connect', Aug 27 19:11:27 daconpi volumio[1245]: address: '127.0.0.1', Aug 27 19:11:27 daconpi volumio[1245]: port: 9879, Aug 27 19:11:27 daconpi volumio[1245]: response: undefined Aug 27 19:11:27 daconpi volumio[1245]: } Aug 27 19:11:27 daconpi volumio[1245]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 19:11:27 daconpi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 27 19:11:27 daconpi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:27 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:27 daconpi go-librespot[1967]: go-librespot daemon starting... Aug 27 19:11:27 daconpi go-librespot[1971]: time="2026-08-27T19:11:27-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:11:27 daconpi go-librespot[1971]: time="2026-08-27T19:11:27-07:00" level=debug msg="app state loaded" Aug 27 19:11:27 daconpi go-librespot[1971]: time="2026-08-27T19:11:27-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=info msg="zeroconf server listening on port 43243" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=debug msg="obtained new client token: AAGAci1A77NZ0KXUZbxWC/mf2Yh4MhId+Lmb8emngymW/fG2foN8QYHmJU8QVpY3P5W7/M8YoUauaN2tECt6nbsAxCBTL3cTNH9/Kkg+sizKKXCKPbGiNL7UnUyWQMwimOxAwm2T1AFGLC9Bum7iqOoVPINFtKc4FULLn5yVjp8XlovJXxo9gzdwcGMLf8BFQqMFK4qqgejv5JgIH2q5gsHA4qLW7KVwCSAP89gPgtsp19k+dqd4RPSH" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=debug msg="completed keyexchange" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=debug msg="completed challenge" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:11:28 daconpi go-librespot[1971]: time="2026-08-27T19:11:28-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:11:28 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:11:28 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 27 19:11:30 daconpi volumio5-onboarding[1555]: time=2026-08-27T19:11:30.888-07:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 Aug 27 19:11:31 daconpi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 27 19:11:31 daconpi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:31 daconpi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:11:31 daconpi go-librespot[1986]: go-librespot daemon starting... Aug 27 19:11:31 daconpi go-librespot[1987]: time="2026-08-27T19:11:31-07:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:11:31 daconpi go-librespot[1987]: time="2026-08-27T19:11:31-07:00" level=debug msg="app state loaded" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=info msg="zeroconf server listening on port 39913" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=debug msg="obtained new client token: AAGISz7ZltzHsJ6tv+WvPkad1d6nEZwYuUf8slLQ/G5rEP2KOzARHHyJQrXCJMl9YHgBC045qObooYlRv1YCjB5+DbjCcLMJtp4iYtwM3gihOsr3ZAp+qFbgagl+3DIsviv56bjHfNNKpH8Wy5rWkGDvwkdr1wC6sc3+Bf6p/mNFenm6arCJtIPftdsFYtodYi8oW8OSkN5Cnq+W4OHKpb8ktxSFYt04v2wlJPKkJaGH8G02681bAVeE" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=debug msg="completed keyexchange" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=debug msg="completed challenge" Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=info msg="authenticated AP" username="12*******59" Aug 27 19:11:32 daconpi sudo[1998]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-27 19:10' Aug 27 19:11:32 daconpi sudo[1998]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:11:32 daconpi go-librespot[1987]: time="2026-08-27T19:11:32-07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 27 19:11:32 daconpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:11:32 daconpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"