Aug 31 08:22:38 player4 ntpd[1004]: CLOCK: time stepped by 1892892.054968 Aug 31 08:22:38 player4 ntpd[1004]: CLOCK: time changed from 2025-08-09 to 2025-08-31 Aug 31 08:22:38 player4 ntpd[1004]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 31 08:22:38 player4 dhcpcd[631]: timed out Aug 31 08:22:38 player4 sh[624]: timed out Aug 31 08:22:38 player4 sh[571]: ifup: failed to bring up eth0 Aug 31 08:22:38 player4 sudo[1379]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:38 player4 systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Aug 31 08:22:38 player4 systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Aug 31 08:22:38 player4 systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Aug 31 08:22:38 player4 systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Aug 31 08:22:38 player4 systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Aug 31 08:22:38 player4 systemd[1]: e2scrub_all.service: Deactivated successfully. Aug 31 08:22:38 player4 systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Aug 31 08:22:38 player4 systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Aug 31 08:22:38 player4 systemd[1]: dpkg-db-backup.service: Deactivated successfully. Aug 31 08:22:38 player4 systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Aug 31 08:22:40 player4 systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 31 08:22:40 player4 volumio[1302]: info: Loading plugin "ytmusic"... Aug 31 08:22:41 player4 volumio-remote-updater[687]: [2025-08-31 08:22:41] [connect] Successful connection Aug 31 08:22:45 player4 volumio[1302]: info: Loading plugin "now_playing"... Aug 31 08:22:47 player4 volumio[1302]: info: Loading plugin "outputs"... Aug 31 08:22:47 player4 volumio[1302]: info: Loading plugin "albumart"... Aug 31 08:22:47 player4 volumio[1302]: info: Plugin example_plugin is not enabled Aug 31 08:22:47 player4 volumio[1302]: info: Loading plugin "inputs"... Aug 31 08:22:47 player4 volumio[1302]: info: Loading plugin "updater_comm"... Aug 31 08:22:47 player4 volumio[1302]: info: Plugin mpdemulation is not enabled Aug 31 08:22:47 player4 volumio[1302]: info: Loading plugin "rest_api"... Aug 31 08:22:47 player4 volumio[1302]: info: Loading plugin "websocket"... Aug 31 08:22:47 player4 volumio[1302]: info: Starting Socket.io Server version 1.7.4 Aug 31 08:22:47 player4 volumio[1302]: info: Loading plugin "touch_display"... Aug 31 08:22:47 player4 volumio[1434]: Forking 3 albumart workers Aug 31 08:22:48 player4 volumio[1302]: info: Applying required configuration parameters for plugin touch_display Aug 31 08:22:48 player4 volumio[1302]: info: Loading i18n strings for locale en Aug 31 08:22:49 player4 volumio[1302]: Updating browse sources language Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::initPlayerControls Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: Express server listening on port 3000 Aug 31 08:22:49 player4 volumio[1302]: [Metrics] WebUI: 17s 904.49ms Aug 31 08:22:49 player4 volumio[1302]: info: CoreStateMachine::resetVolumioState Aug 31 08:22:49 player4 volumio[1302]: info: CoreStateMachine::getcurrentVolume Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::volumioRetrievevolume Aug 31 08:22:49 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:22:49 player4 volumio[1302]: info: Volumio Network Manager: Network status updated: 2 Aug 31 08:22:50 player4 volumio[1302]: info: VolumeController:: Volume=68 Mute =false Aug 31 08:22:50 player4 volumio[1302]: info: CoreStateMachine::pushState Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioPushState Aug 31 08:22:50 player4 volumio[1302]: info: CoreStateMachine::updateTrackBlock Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrackBlock Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioRetrievevolume Aug 31 08:22:50 player4 volumio[1445]: Starting albumart workers Aug 31 08:22:50 player4 volumio[1302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Aug 31 08:22:50 player4 volumio[1302]: info: Reloading queue from file Aug 31 08:22:50 player4 volumio[1302]: info: CoreStateMachine::setRepeat null single undefined Aug 31 08:22:50 player4 volumio[1302]: info: CoreStateMachine::pushState Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioPushState Aug 31 08:22:50 player4 volumio[1302]: info: CoreStateMachine::setRandom true Aug 31 08:22:50 player4 volumio[1302]: info: CoreStateMachine::pushState Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioPushState Aug 31 08:22:50 player4 volumio[1302]: info: Setting Device type: Raspberry PI Aug 31 08:22:50 player4 volumio[1302]: info: VolumeController:: Volume=68 Mute =false Aug 31 08:22:50 player4 volumio[1302]: info: CoreStateMachine::pushState Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioPushState Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: A device disappeared from network Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: Browse raised the following error TypeError: Cannot read properties of undefined (reading 'toLowerCase') Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: adding bc522b11-0bb8-45a5-bebf-ecd9824669ec Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: Found device Player4 Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: this is already registered, bc522b11-0bb8-45a5-bebf-ecd9824669ec Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: Found device Player4 Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: A device disappeared from network Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: Device player4 disappeared from network Aug 31 08:22:50 player4 volumio[1302]: info: Completed loading Core Plugins Aug 31 08:22:50 player4 volumio[1302]: info: Preparing to generate the ALSA configuration file Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: adding bc522b11-0bb8-45a5-bebf-ecd9824669ec Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: Found device Player4 Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: this is already registered, bc522b11-0bb8-45a5-bebf-ecd9824669ec Aug 31 08:22:50 player4 volumio[1302]: info: Discovery: Found device Player4 Aug 31 08:22:50 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:50 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:50 player4 volumio[1302]: info: Asound.conf file unchanged, so no further update is needed Aug 31 08:22:50 player4 volumio[1302]: info: Output device has changed, restarting MPD Aug 31 08:22:51 player4 volumio[1444]: Starting albumart workers Aug 31 08:22:51 player4 sudo[1493]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 08:22:51 player4 sudo[1493]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:51 player4 volumio[1302]: info: ___________ START PLUGINS ___________ Aug 31 08:22:51 player4 sudo[1493]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:51 player4 volumio[1302]: info: ControllerMpd::onStart: Initializing MPD Aug 31 08:22:51 player4 volumio[1302]: info: Creating MPD Configuration file Aug 31 08:22:51 player4 volumio[1446]: Starting albumart workers Aug 31 08:22:51 player4 sudo[1495]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 08:22:51 player4 sudo[1498]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 08:22:51 player4 sudo[1498]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:51 player4 sudo[1498]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:51 player4 sudo[1495]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:51 player4 volumio[1302]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 08:22:51 player4 volumio[1302]: info: [1756608771152] CoreMusicLibrary::Adding element Last_100 Aug 31 08:22:51 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 08:22:51 player4 volumio[1302]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 08:22:51 player4 volumio[1302]: info: [1756608771155] CoreMusicLibrary::Adding element Webradio Aug 31 08:22:51 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 08:22:51 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 08:22:51 player4 systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 31 08:22:51 player4 sudo[1502]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 08:22:51 player4 sudo[1502]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:51 player4 volumio[1302]: info: Initializing BBC Radios Aug 31 08:22:51 player4 systemd[1]: mpd.service: Deactivated successfully. Aug 31 08:22:51 player4 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 08:22:51 player4 systemd[1]: mpd.service: Consumed 3.273s CPU time. Aug 31 08:22:51 player4 systemd[1]: mpd.socket: Deactivated successfully. Aug 31 08:22:51 player4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 08:22:51 player4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 08:22:51 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 08:22:51 player4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 08:22:51 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:22:51 player4 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 08:22:51 player4 volumio[1302]: info: Creating Spotify config file Aug 31 08:22:51 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:51 player4 sudo[1519]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 08:22:51 player4 sudo[1519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 08:22:51 player4 sudo[1519]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:52 player4 volumio[1302]: info: [ytcr] Data store TTL expired - clearing it... Aug 31 08:22:52 player4 volumio[1302]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 08:22:52 player4 volumio[1302]: info: [1756608772449] CoreMusicLibrary::Adding element YouTube Music Aug 31 08:22:52 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 08:22:52 player4 volumio[1302]: Cannot find translation for source YouTube Music Aug 31 08:22:52 player4 volumio[1302]: info: [now-playing] ConfigUpdater: config is up to date. Aug 31 08:22:52 player4 volumio[1302]: info: Loading i18n strings for locale en Aug 31 08:22:52 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 08:22:52 player4 volumio[1302]: info: Volumio Calling Home Aug 31 08:22:53 player4 sudo[1544]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Aug 31 08:22:53 player4 sudo[1546]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Aug 31 08:22:53 player4 sudo[1546]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:53 player4 sudo[1544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:53 player4 sudo[1548]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Aug 31 08:22:53 player4 sudo[1548]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:53 player4 systemd[1]: Reloading. Aug 31 08:22:53 player4 mpd[1521]: 2025-08-31T08:22:53 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 31 08:22:53 player4 volumio[1302]: info: [now-playing] App is listening on port 4004. Aug 31 08:22:53 player4 volumio[1302]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Aug 31 08:22:53 player4 volumio[1302]: info: touch_display: Backlight interface detected. Aug 31 08:22:53 player4 volumio[1302]: info: MPD Permissions set Aug 31 08:22:53 player4 volumio[1302]: info: MPD Permissions set Aug 31 08:22:53 player4 volumio[1302]: info: Spotify config file written Aug 31 08:22:53 player4 volumio[1302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Aug 31 08:22:53 player4 volumio[1302]: info: Volumio called home Aug 31 08:22:53 player4 sudo[1575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 31 08:22:53 player4 sudo[1575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: No need to fix Spotify hosts Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:53 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:54 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:22:54 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 08:22:54 player4 systemd[1]: Started mpd.service - Music Player Daemon. Aug 31 08:22:54 player4 sudo[1502]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:54 player4 sudo[1495]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:54 player4 sudo[1548]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:54 player4 systemd[1]: Reloading. Aug 31 08:22:54 player4 sudo[1619]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/10-0045/brightness Aug 31 08:22:54 player4 sudo[1619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:54 player4 sudo[1619]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: systemctl daemon-reload succeeded. Aug 31 08:22:55 player4 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 31 08:22:55 player4 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 31 08:22:55 player4 sudo[1546]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:55 player4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:22:55 player4 go-librespot[1623]: go-librespot daemon starting... Aug 31 08:22:55 player4 sudo[1575]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:55 player4 sudo[1626]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Aug 31 08:22:55 player4 sudo[1544]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:55 player4 sudo[1626]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: Raspberry Pi Foundation touch screen detected. Aug 31 08:22:55 player4 sudo[1638]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Aug 31 08:22:55 player4 sudo[1638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:55 player4 sudo[1638]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:55 player4 sudo[1632]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Aug 31 08:22:55 player4 sudo[1632]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:22:55 player4 sudo[1632]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: File permissions for backlight brightness control set. Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: systemctl disable getty@tty1.service succeeded. Aug 31 08:22:55 player4 volumio[1302]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Aug 31 08:22:55 player4 volumio[1302]: SPOTIFY: BQCUBJuCb05ePUN7MmdUungko8rQgZOk6USlGs-8HvY-IXzV15cSssNf5Aq7VaobrFqdCNvgyG7jMig844zfGk5_bVsK6kSEtrYZXr1tUY9jEQ5HrE5yI8xlC5at0FpaswyTZ4BoIftKxINdFx8w2zfqJjM-VYab6DqQcvgbwk7hUB0tjetOJ7kRPk-0rym_PhHmFWkeOytqqmLWO2xhTXbNEFpKvwNmXuU1EU5MdH_Z1W4gGWx2MKCOH42YrityFaKEmhYYuf_Jnq6i_PSgLwb7eMszx-r_xBftVJ1vqxtDpDC8v48 Aug 31 08:22:55 player4 volumio[1302]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Aug 31 08:22:55 player4 volumio[1302]: info: New Spotify access token = BQCUBJuCb05ePUN7MmdUungko8rQgZOk6USlGs-8HvY-IXzV15cSssNf5Aq7VaobrFqdCNvgyG7jMig844zfGk5_bVsK6kSEtrYZXr1tUY9jEQ5HrE5yI8xlC5at0FpaswyTZ4BoIftKxINdFx8w2zfqJjM-VYab6DqQcvgbwk7hUB0tjetOJ7kRPk-0rym_PhHmFWkeOytqqmLWO2xhTXbNEFpKvwNmXuU1EU5MdH_Z1W4gGWx2MKCOH42YrityFaKEmhYYuf_Jnq6i_PSgLwb7eMszx-r_xBftVJ1vqxtDpDC8v48 Aug 31 08:22:55 player4 volumio[1302]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 31 08:22:55 player4 systemd[1]: Started volumio-kiosk.service - Volumio Kiosk. Aug 31 08:22:55 player4 sudo[1626]: pam_unix(sudo:session): session closed for user root Aug 31 08:22:55 player4 go-librespot[1629]: time="2025-08-31T08:22:55+05:30" level=info msg="running go-librespot 0.3.2" Aug 31 08:22:55 player4 go-librespot[1629]: time="2025-08-31T08:22:55+05:30" level=debug msg="no app state found" Aug 31 08:22:55 player4 go-librespot[1629]: time="2025-08-31T08:22:55+05:30" level=debug msg="stored credentials not found" Aug 31 08:22:55 player4 go-librespot[1629]: time="2025-08-31T08:22:55+05:30" level=info msg="generated new device id: e07327b90b4b7128bf8f8e60567f84b1a839d3b8" Aug 31 08:22:55 player4 go-librespot[1629]: time="2025-08-31T08:22:55+05:30" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 08:22:55 player4 volumio[1302]: error: MPD error: The expression evaluated to a falsy value: Aug 31 08:22:55 player4 volumio[1302]: assert.ok(self.idling) Aug 31 08:22:55 player4 volumio[1302]: error: The expression evaluated to a falsy value: Aug 31 08:22:55 player4 volumio[1302]: assert.ok(self.idling) Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: systemctl stop getty@tty1.service succeeded. Aug 31 08:22:55 player4 volumio[1302]: info: MPD running with PID1521 Aug 31 08:22:55 player4 volumio[1302]: ,establishing connection Aug 31 08:22:55 player4 volumio[1302]: error: updateQueue error: null Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Aug 31 08:22:55 player4 volumio[1302]: info: touch_display: Volumio Kiosk started. Aug 31 08:22:55 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:55 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:55 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:55 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:56 player4 startx[1666]: X.Org X Server 1.21.1.7 Aug 31 08:22:56 player4 startx[1666]: X Protocol Version 11, Revision 0 Aug 31 08:22:56 player4 startx[1666]: Current Operating System: Linux player4 6.12.34-v7l+ #1889 SMP Mon Jun 23 11:08:21 BST 2025 armv7l Aug 31 08:22:56 player4 startx[1666]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory numa_policy=interleave nvme.max_host_mem_size_mb=0 snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_hdmi=0 video=HDMI-A-1:640x480M@60D numa=fake=1 system_heap.max_order=0 smsc95xx.macaddr=2C:CF:67:05:40:92 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=9aae75e3-71dc-4cd8-81c2-e432641843a7 imgfile=/volumio_current.sqsh bootpart=UUID=0F99-EC7C datapart=UUID=6fee81e4-7bf1-40e5-aaed-c3a77319b96c uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Aug 31 08:22:56 player4 startx[1666]: xorg-server 2:21.1.7-3+rpt3+deb12u9 (https://www.debian.org/support) Aug 31 08:22:56 player4 startx[1666]: Current version of pixman: 0.44.0 Aug 31 08:22:56 player4 startx[1666]: Before reporting problems, check http://wiki.x.org Aug 31 08:22:56 player4 startx[1666]: to make sure that you have the latest version. Aug 31 08:22:56 player4 startx[1666]: Markers: (--) probed, (**) from config file, (==) default setting, Aug 31 08:22:56 player4 startx[1666]: (++) from command line, (!!) notice, (II) informational, Aug 31 08:22:56 player4 startx[1666]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Aug 31 08:22:56 player4 startx[1666]: (==) Log file: "/var/log/Xorg.0.log", Time: Sun Aug 31 08:22:56 2025 Aug 31 08:22:56 player4 startx[1666]: (==) Using config directory: "/etc/X11/xorg.conf.d" Aug 31 08:22:56 player4 startx[1666]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Aug 31 08:22:56 player4 volumio[1302]: error: updateQueue error: null Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=info msg="zeroconf server listening on port 32993" Aug 31 08:22:56 player4 volumio[1302]: info: touch_display: X display number found: 0 Aug 31 08:22:56 player4 volumio[1302]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=debug msg="obtained new client token: AABQzSqAGTOiDwsCkDUYhnowpqVKZu3iZvcPcF61d5nMvJbpZ3KwMJz2d2Tls90QSRFEwSXW7qxkblKARb59knTDRc0JOiX0VhZirxccj0mt4rHHcdvtg9BdpjgnycWlUN0xsxQ/IbKguP3Q4OnX/9HG5upFA0sEh5yUlpUo2ntf9e2FiblVJolTBxTa5pvuC/9jN8PxCG2l9L6TW2cRMPlhNa+ZZYeyEbvxsJW6v1JMEgvzTknZoIjB" Aug 31 08:22:56 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:56 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 08:22:56 player4 volumio[1302]: info: touch_display: X display number found: 0 Aug 31 08:22:56 player4 volumio-remote-updater[687]: [2025-08-31 08:22:56] [connect] Successful connection Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=debug msg="completed keyexchange" Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=debug msg="completed challenge" Aug 31 08:22:56 player4 volumio-remote-updater[687]: [2025-08-31 08:22:56] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1756608776 101 Aug 31 08:22:56 player4 volumio[1302]: 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: 3 Aug 31 08:22:56 player4 go-librespot[1629]: time="2025-08-31T08:22:56+05:30" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Aug 31 08:22:56 player4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 08:22:56 player4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 08:22:56 player4 volumio[1302]: SPOTIFY: User informations: {"country":"IN","display_name":"Austin","email":"njaustin123@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31pizlsiju3dxpbxd2ytuog3tvre"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/31pizlsiju3dxpbxd2ytuog3tvre","id":"31pizlsiju3dxpbxd2ytuog3tvre","images":[],"product":"premium","type":"user","uri":"spotify:user:31pizlsiju3dxpbxd2ytuog3tvre"} Aug 31 08:22:56 player4 volumio[1302]: info: Spotify Successfully logged in Aug 31 08:22:56 player4 volumio[1302]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 08:22:56 player4 volumio[1302]: info: [1756608776885] CoreMusicLibrary::Adding element Spotify Aug 31 08:22:56 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 08:22:56 player4 volumio[1302]: Cannot find translation for source YouTube Music Aug 31 08:22:56 player4 volumio[1302]: Cannot find translation for source Spotify Aug 31 08:22:58 player4 kernel: ------------[ cut here ]------------ Aug 31 08:22:58 player4 kernel: WARNING: CPU: 2 PID: 1666 at drivers/gpu/drm/vc4/vc4_hvs.c:1064 __vc4_hvs_stop_channel+0x168/0x1dc [vc4] Aug 31 08:22:58 player4 kernel: Modules linked in: cmac algif_hash aes_arm_bs crypto_simd cryptd aes_arm aes_generic algif_skcipher af_alg bnep nft_chain_nat joydev xt_REDIRECT nf_nat nf_conntrack nf_defrag_ipv6 tc358762 nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink brcmfmac_wcc 8021q garp stp llc binfmt_misc brcmfmac hci_uart brcmutil cfg80211 raspberrypi_hwmon btbcm edt_ft5x06 bluetooth snd_usb_audio snd_hwdep snd_usbmidi_lib snd_seq_midi vc4 ecdh_generic snd_seq_midi_event ecc rfkill libaes snd_rawmidi rpi_hevc_dec snd_soc_hdmi_codec raspberrypi_gpiomem drm_display_helper cec drm_dma_helper snd_soc_core snd_bcm2835(C) bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_isp(C) snd_compress snd_pcm_dmaengine v4l2_mem2mem snd_pcm bcm2835_mmal_vchiq(C) vc_sm_cma(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_seq videodev snd_seq_device videobuf2_common snd_timer mc snd nvmem_rmem uio_pdrv_genirq uio i2c_dev dm_mod ip_tables x_tables ipv6 squashfs overlay nls_iso8859_1 fuse rpi_panel_attiny_regulator Aug 31 08:22:58 player4 kernel: regmap_i2c v3d gpu_sched drm_shmem_helper drm_kms_helper i2c_mux_pinctrl i2c_mux i2c_brcmstb i2c_bcm2835 panel_simple drm drm_panel_orientation_quirks backlight Aug 31 08:22:58 player4 kernel: CPU: 2 UID: 0 PID: 1666 Comm: Xorg Tainted: G C 6.12.34-v7l+ #1889 Aug 31 08:22:58 player4 kernel: Tainted: [C]=CRAP Aug 31 08:22:58 player4 kernel: Hardware name: BCM2711 Aug 31 08:22:58 player4 kernel: Call trace: Aug 31 08:22:58 player4 kernel: unwind_backtrace from show_stack+0x18/0x1c Aug 31 08:22:58 player4 kernel: show_stack from dump_stack_lvl+0x5c/0x80 Aug 31 08:22:58 player4 kernel: dump_stack_lvl from __warn+0x88/0x124 Aug 31 08:22:58 player4 kernel: __warn from warn_slowpath_fmt+0x184/0x190 Aug 31 08:22:58 player4 kernel: warn_slowpath_fmt from __vc4_hvs_stop_channel+0x168/0x1dc [vc4] Aug 31 08:22:58 player4 kernel: __vc4_hvs_stop_channel [vc4] from vc4_crtc_disable+0x138/0x1dc [vc4] Aug 31 08:22:58 player4 kernel: vc4_crtc_disable [vc4] from vc4_crtc_atomic_disable+0x9c/0xc0 [vc4] Aug 31 08:22:58 player4 kernel: vc4_crtc_atomic_disable [vc4] from disable_outputs+0x268/0x3a0 [drm_kms_helper] Aug 31 08:22:58 player4 kernel: disable_outputs [drm_kms_helper] from drm_atomic_helper_commit_modeset_disables+0x18/0x3c [drm_kms_helper] Aug 31 08:22:58 player4 kernel: drm_atomic_helper_commit_modeset_disables [drm_kms_helper] from vc4_atomic_commit_tail+0x100/0x998 [vc4] Aug 31 08:22:58 player4 kernel: vc4_atomic_commit_tail [vc4] from commit_tail+0xa4/0x18c [drm_kms_helper] Aug 31 08:22:58 player4 kernel: commit_tail [drm_kms_helper] from drm_atomic_helper_commit+0x140/0x164 [drm_kms_helper] Aug 31 08:22:58 player4 kernel: drm_atomic_helper_commit [drm_kms_helper] from drm_atomic_commit+0xc8/0x100 [drm] Aug 31 08:22:58 player4 kernel: drm_atomic_commit [drm] from drm_atomic_helper_set_config+0x90/0xc8 [drm_kms_helper] Aug 31 08:22:58 player4 kernel: drm_atomic_helper_set_config [drm_kms_helper] from drm_mode_setcrtc+0x200/0x814 [drm] Aug 31 08:22:58 player4 kernel: drm_mode_setcrtc [drm] from drm_ioctl+0x2b4/0x4d0 [drm] Aug 31 08:22:58 player4 kernel: drm_ioctl [drm] from sys_ioctl+0x130/0xbcc Aug 31 08:22:58 player4 kernel: sys_ioctl from ret_fast_syscall+0x0/0x5c Aug 31 08:22:58 player4 kernel: Exception stack(0xf0d5dfa8 to 0xf0d5dff0) Aug 31 08:22:58 player4 kernel: dfa0: 0000000c be9aa9d0 0000000c c06864a2 be9aa9d0 be9aa9b0 Aug 31 08:22:58 player4 kernel: dfc0: 0000000c be9aa9d0 c06864a2 00000036 be9aaa88 014c4ea0 011a3630 00000000 Aug 31 08:22:58 player4 kernel: dfe0: 00000000 be9aa998 b69a5000 b6928174 Aug 31 08:22:58 player4 kernel: ---[ end trace 0000000000000000 ]--- Aug 31 08:22:58 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:58 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:58 player4 volumio[1302]: info: [yt-cast-receiver] DIAL server listening on port 8098 Aug 31 08:22:58 player4 volumio[1302]: info: CoreCommandRouter::volumioRetrievevolume Aug 31 08:22:58 player4 volumio[1302]: info: touch_display: Setting screensaver timeout to 30 seconds. Aug 31 08:22:58 player4 volumio[1302]: info: VolumeController:: Volume=68 Mute =false Aug 31 08:22:58 player4 volumio[1302]: info: CoreCommandRouter::volumioGetState Aug 31 08:22:58 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:58 player4 volumio[1302]: info: CoreStateMachine::pushState Aug 31 08:22:58 player4 volumio[1302]: info: CorePlayQueue::getTrack 0 Aug 31 08:22:58 player4 volumio[1302]: info: CoreCommandRouter::volumioPushState Aug 31 08:22:58 player4 volumio[1302]: info: Completed starting Core Plugins Aug 31 08:22:58 player4 volumio[1302]: info: ------------------------------------------- Aug 31 08:22:58 player4 volumio[1302]: info: ----- MyVolumio plugins startup ---- Aug 31 08:22:58 player4 volumio[1302]: info: ------------------------------------------- Aug 31 08:22:58 player4 volumio[1302]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 31 08:22:58 player4 volumio[1302]: info: go-librespot daemon successfully initialized Aug 31 08:22:58 player4 systemd[1]: systemd-timedated.service: Deactivated successfully. Aug 31 08:22:59 player4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 31 08:22:59 player4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:22:59 player4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:22:59 player4 go-librespot[1703]: go-librespot daemon starting... Aug 31 08:22:59 player4 go-librespot[1704]: time="2025-08-31T08:22:59+05:30" level=info msg="running go-librespot 0.3.2" Aug 31 08:22:59 player4 go-librespot[1704]: time="2025-08-31T08:22:59+05:30" level=debug msg="app state loaded" Aug 31 08:22:59 player4 go-librespot[1704]: time="2025-08-31T08:22:59+05:30" level=debug msg="stored credentials not found" Aug 31 08:22:59 player4 go-librespot[1704]: time="2025-08-31T08:22:59+05:30" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=info msg="zeroconf server listening on port 44389" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=debug msg="obtained new client token: AAB72J1+IFzAUvHC8HOgv5YPYDong6msSEK9R0P0CDYVMVIqU8l5EmnMSbjO3Ql/qp0bfMcPfMs/U4hmY/N+5DYgNR/Kxids+6Ncwc54BQxfi85kom4ug1LQkW3LU+O/fibEht1RucFlIYDdi95/5crme6xoOP9157dz/sR5kEeJnD+I3Gmfwmr1M1CJBAeBYvS22firKxzZpdFmKm4qPqfUK0QUdBnfClLnsq+mZQaZdnPwypBiSiRK" Aug 31 08:23:00 player4 volumio[1302]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=warning msg="failed to connect to AP ap-gae2.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.241.202:443: connect: connection refused" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=debug msg="connected to ap-gae2.spotify.com:80" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=debug msg="completed keyexchange" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=debug msg="completed challenge" Aug 31 08:23:00 player4 go-librespot[1704]: time="2025-08-31T08:23:00+05:30" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Aug 31 08:23:00 player4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 08:23:00 player4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 08:23:01 player4 volumio[1302]: info: Initializing connection to go-librespot Websocket Aug 31 08:23:01 player4 volumio[1302]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 08:23:04 player4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 31 08:23:04 player4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:04 player4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:04 player4 go-librespot[1757]: go-librespot daemon starting... Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=info msg="running go-librespot 0.3.2" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="app state loaded" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="stored credentials not found" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=info msg="zeroconf server listening on port 34917" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="obtained new client token: AAD4R1QrTPEyn93E8Gyz1zgG28SFy8Yq/vCeq/ND2+MaLzdWN6v60PTk5/GOzmBG96CT2BKHgwa5ZKKu7+aeJRkR+8ogsQS4RMMQhmJPWpiFhHcWT9lnCx9zQKlpEkQIrr13O8MLPaCI2BqS1goGThJ13nsXiu+ezxYtqbODMvrCw8tbEMb+PoZYc0uA2xDMyWmuK/fbaKCELQIc2DedlRmIuYyWd112V4q9bvdIWJZ+uaB6wQyhAXxt" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="completed keyexchange" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=debug msg="completed challenge" Aug 31 08:23:04 player4 go-librespot[1758]: time="2025-08-31T08:23:04+05:30" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Aug 31 08:23:04 player4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 08:23:04 player4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 08:23:04 player4 volumio[1302]: info: Initializing connection to go-librespot Websocket Aug 31 08:23:04 player4 volumio[1302]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 31 08:23:07 player4 volumio[1302]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 31 08:23:07 player4 volumio[1302]: info: Adding plugin bluetooth to MyMusic Plugins Aug 31 08:23:07 player4 volumio[1302]: info: Adding plugin multiroom to MyMusic Plugins Aug 31 08:23:07 player4 volumio[1302]: info: Adding plugin metavolumio to MyMusic Plugins Aug 31 08:23:07 player4 volumio[1302]: info: Adding plugin cd_controller to MyMusic Plugins Aug 31 08:23:08 player4 volumio[1302]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 31 08:23:08 player4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 31 08:23:08 player4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:08 player4 volumio[1302]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 31 08:23:08 player4 volumio[1302]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 31 08:23:08 player4 volumio[1302]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 31 08:23:08 player4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:08 player4 go-librespot[1797]: go-librespot daemon starting... Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=info msg="running go-librespot 0.3.2" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="app state loaded" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="stored credentials not found" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=info msg="zeroconf server listening on port 38359" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="obtained new client token: AADHsu7Ifrbin4CboyUS34vYYA2xnNXP5SWjzaqIJQwa1xhJ1tIKcbgKjZHZl6GGR++3ZmnoLUUA+KQeKIbuHAd6Zjfp9i+vyeEplYb3UngyeTOtQDoSNmzCfoA6JfxrN7gIwKDp35knNcZDJ75RYksTLkXIgaFHpvP99l9iQ1JllOTo91fKRcZpjg7XZLPLCM4SUxlTYTiT1DUxnqSQZy1N7gJP49IZ57v7N7uP0XpyBI86BVUtsLBw" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="completed keyexchange" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=debug msg="completed challenge" Aug 31 08:23:08 player4 go-librespot[1798]: time="2025-08-31T08:23:08+05:30" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Aug 31 08:23:08 player4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 08:23:08 player4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 08:23:10 player4 volumio[1302]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 31 08:23:10 player4 volumio[1302]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 31 08:23:10 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:23:10 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:23:10 player4 volumio[1302]: info: Starting MyVolumio Remote Streaming Endpoints Aug 31 08:23:10 player4 volumio[1302]: info: MyVolumio login type: Token Aug 31 08:23:10 player4 volumio[1302]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 31 08:23:10 player4 volumio[1302]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 31 08:23:12 player4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 31 08:23:12 player4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:12 player4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:12 player4 go-librespot[1805]: go-librespot daemon starting... Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=info msg="running go-librespot 0.3.2" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="app state loaded" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="stored credentials not found" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=info msg="zeroconf server listening on port 40699" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="obtained new client token: AACJr1UOBXPnRKaKHcwWUGPrXwIYUJ3/Hk/q8rI82ABNgL/gRQmCh6YSxnd5M2iSCMVJ1qQQbHmVPhMYacJiA0y7CsXmCNBs+sWMPsRonVXYKJBiNDN1JRrU9n9rg3vysM217ceIPw/w/uOnfiKGwKDCL0XLpn746tFciAJK7u4RoeC3FkoU8t4JgXdcIQ6W/4ESkNnAbLrTNumoYIRL7ZHUGYhE6GSNcWuLC5qJ5ZOTU246JBB09MkR" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="completed keyexchange" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=debug msg="completed challenge" Aug 31 08:23:12 player4 go-librespot[1806]: time="2025-08-31T08:23:12+05:30" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Aug 31 08:23:12 player4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 08:23:12 player4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 08:23:13 player4 volumio[1302]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 31 08:23:13 player4 volumio[1302]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 31 08:23:13 player4 volumio[1302]: info: Streaming services startup Aug 31 08:23:13 player4 volumio[1302]: info: Starting Streaming Daemon Aug 31 08:23:13 player4 volumio[1302]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 31 08:23:13 player4 sudo[1814]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 31 08:23:13 player4 sudo[1814]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:23:13 player4 volumio[1302]: info: Initializing connection to go-librespot Websocket Aug 31 08:23:13 player4 sudo[1814]: pam_unix(sudo:session): session closed for user root Aug 31 08:23:13 player4 volumio[1302]: error: Cannot start Volumio Streaming Daemon Aug 31 08:23:13 player4 volumio[1302]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 31 08:23:13 player4 volumio[1302]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 31 08:23:13 player4 volumio[1302]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 08:23:13 player4 volumio[1302]: error: MyVolumio Custom Token format not valid, refreshing it Aug 31 08:23:15 player4 volumio[1302]: info: MyVolumio login type: Token Aug 31 08:23:16 player4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 31 08:23:16 player4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:16 player4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:16 player4 go-librespot[1837]: go-librespot daemon starting... Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=info msg="running go-librespot 0.3.2" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="app state loaded" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="stored credentials not found" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=info msg="zeroconf server listening on port 45381" Aug 31 08:23:16 player4 volumio[1302]: info: Initializing connection to go-librespot Websocket Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="new websocket client" Aug 31 08:23:16 player4 volumio[1302]: info: Connection to go-librespot Websocket established Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="obtained new client token: AACB2znky+4HGO3hPIZdBrcPCH+Y9AWsnc0W402WmIDSTvbvzNk57hs8DvgQ1epgeLuvTKcC5GWmBlcnzT0ujzAkYYjO4Lv5VuGRFPdUsE2UwerejA0fl5buqn2qfNWAaZapsT2/tc6/Cs4pPCjPUxjbU5jmXvPVEQNPI57zz9FrWmmU9/XKNTQOsyB2KLq7WgrqemBMDFUztBfxgfYzE9cYuq0yN2F/kaw0LRC58clMkmdsmjn5bG6Y" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="completed keyexchange" Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=debug msg="completed challenge" Aug 31 08:23:16 player4 volumio[1302]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 31 08:23:16 player4 go-librespot[1838]: time="2025-08-31T08:23:16+05:30" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Aug 31 08:23:16 player4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 08:23:16 player4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 08:23:16 player4 volumio[1302]: info: Connection to go-librespot Websocket closed Aug 31 08:23:17 player4 volumio[1302]: info: MyVolumio token set successfully Aug 31 08:23:17 player4 volumio[1302]: info: MYVOLUMIO: Adding device Aug 31 08:23:17 player4 volumio[1302]: info: MYVOLUMIO: Evaluating Server Aug 31 08:23:18 player4 volumio[1302]: info: MyVolumio status changed Aug 31 08:23:18 player4 volumio[1302]: info: Streaming services startup Aug 31 08:23:18 player4 volumio[1302]: info: Starting Streaming Daemon Aug 31 08:23:18 player4 volumio[1302]: info: Removing browser output: myVolumio user plan is not superstar Aug 31 08:23:18 player4 volumio[1302]: info: Removing audio output: Aug 31 08:23:18 player4 volumio[1302]: info: Stoppping Tunnel 1 Aug 31 08:23:18 player4 sudo[1864]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 31 08:23:18 player4 sudo[1864]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:23:18 player4 sudo[1866]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 31 08:23:18 player4 sudo[1864]: pam_unix(sudo:session): session closed for user root Aug 31 08:23:18 player4 volumio[1302]: error: Cannot start Volumio Streaming Daemon Aug 31 08:23:18 player4 volumio[1302]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 31 08:23:18 player4 volumio[1302]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 31 08:23:18 player4 sudo[1866]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 08:23:18 player4 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 31 08:23:18 player4 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 31 08:23:18 player4 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 31 08:23:18 player4 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 31 08:23:18 player4 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 31 08:23:18 player4 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 31 08:23:18 player4 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 31 08:23:18 player4 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 31 08:23:18 player4 sudo[1866]: pam_unix(sudo:session): session closed for user root Aug 31 08:23:18 player4 volumio[1302]: info: Remote SSH Stopped Aug 31 08:23:18 player4 volumio[1302]: info: Setting Geolocation for MyVolumio to as2 Aug 31 08:23:18 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:23:18 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:23:18 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:23:18 player4 volumio[1302]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Aug 31 08:23:19 player4 volumio[1302]: info: Updating MyVolumio device info Aug 31 08:23:19 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:23:19 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:23:19 player4 volumio[1302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 08:23:19 player4 volumio[1302]: info: Getting Spotify volume Aug 31 08:23:19 player4 volumio[1302]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 08:23:19 player4 volumio[1302]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 08:23:19 player4 volumio[1302]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 31 08:23:19 player4 volumio[1302]: errno: -111, Aug 31 08:23:19 player4 volumio[1302]: code: 'ECONNREFUSED', Aug 31 08:23:19 player4 volumio[1302]: syscall: 'connect', Aug 31 08:23:19 player4 volumio[1302]: address: '127.0.0.1', Aug 31 08:23:19 player4 volumio[1302]: port: 9879, Aug 31 08:23:19 player4 volumio[1302]: response: undefined Aug 31 08:23:19 player4 volumio[1302]: } Aug 31 08:23:19 player4 volumio[1302]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 08:23:20 player4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 31 08:23:20 player4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:20 player4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 08:23:20 player4 go-librespot[1881]: go-librespot daemon starting... Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=info msg="running go-librespot 0.3.2" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="app state loaded" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="stored credentials not found" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=info msg="zeroconf server listening on port 40641" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="obtained new client token: AAB6OwrxSZ+xeG8BLSAkGQnlJfdzcNkVAAdgYXUVvD7MROozxvvesrDxX1reJsWWRD7fFvTAB0AtNoHnW8CE2WD5l140n1u7hSf52iu4jylda60tz75yPyEWIS+SrVu1PI/nIJChwlmxrDg1w7yFNd4SMIbOd6NvS70F0iiewcKaYnlp6fP9q+aQPb3Puf/opa0q/1mrz6qnoj3Gu1W4dde6KBYCWLYwlxRQsJzxtDFTuOaKQmZafskP" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="completed keyexchange" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=debug msg="completed challenge" Aug 31 08:23:20 player4 go-librespot[1882]: time="2025-08-31T08:23:20+05:30" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Aug 31 08:23:20 player4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 08:23:20 player4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 08:23:21 player4 sudo[1891]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-08-31 08:22' Aug 31 08:23:21 player4 sudo[1891]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 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="477d19cd2b4ebf4b4c802be78e00bbb657e83aea" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Aug 2 17:34:53 UTC 2025" VOLUMIO_VERSION="4.021" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6199706cbb86ad1289fc7190b8a00601"