Dec 12 15:47:01 volumio1 ntpd[1070]: CLOCK: time stepped by 30.618691 Dec 12 15:47:01 volumio1 ntpd[1070]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Dec 12 15:47:02 volumio1 volumio[1324]: info: Starting UPNP Browser Dec 12 15:47:02 volumio1 volumio[1324]: info: Loading plugin "alarm-clock"... Dec 12 15:47:02 volumio1 volumio[1324]: info: Loading plugin "airplay_emulation"... Dec 12 15:47:02 volumio1 volumio[1324]: info: Starting Shairport Sync Dec 12 15:47:02 volumio1 volumio[1324]: info: Loading plugin "last_100"... Dec 12 15:47:02 volumio1 volumio[1324]: info: Loading plugin "webradio"... Dec 12 15:47:02 volumio1 volumio[1324]: info: Loading plugin "i2s_dacs"... Dec 12 15:47:02 volumio1 volumio[1324]: info: I2S DAC not set, start Auto-detection Dec 12 15:47:02 volumio1 volumio[1324]: info: Loading plugin "volumiodiscovery"... Dec 12 15:47:02 volumio1 volumio[1324]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 12 15:47:02 volumio1 volumio[1324]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 15:47:02 volumio1 volumio[1324]: *** WARNING *** For more information see Dec 12 15:47:02 volumio1 volumio[1324]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 12 15:47:02 volumio1 volumio[1324]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 15:47:02 volumio1 node[1324]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 12 15:47:02 volumio1 volumio[1324]: *** WARNING *** For more information see Dec 12 15:47:02 volumio1 node[1324]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 15:47:02 volumio1 node[1324]: *** WARNING *** For more information see Dec 12 15:47:02 volumio1 node[1324]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 12 15:47:02 volumio1 node[1324]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 15:47:02 volumio1 node[1324]: *** WARNING *** For more information see Dec 12 15:47:02 volumio1 volumio[1324]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 12 15:47:02 volumio1 volumio[1324]: info: Discovery: Started advertising with name: Volumio1 Dec 12 15:47:02 volumio1 sudo[1408]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:02 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 15:47:02 volumio1 volumio[1324]: info: Loading plugin "spop"... Dec 12 15:47:04 volumio1 volumio[1324]: info: Loading plugin "now_playing"... Dec 12 15:47:07 volumio1 volumio[1324]: info: Loading plugin "outputs"... Dec 12 15:47:07 volumio1 volumio[1324]: info: Loading plugin "albumart"... Dec 12 15:47:07 volumio1 volumio[1324]: info: Plugin example_plugin is not enabled Dec 12 15:47:07 volumio1 volumio[1324]: info: Loading plugin "inputs"... Dec 12 15:47:07 volumio1 volumio[1324]: info: Loading plugin "updater_comm"... Dec 12 15:47:07 volumio1 volumio[1324]: info: Plugin mpdemulation is not enabled Dec 12 15:47:07 volumio1 volumio[1324]: info: Loading plugin "rest_api"... Dec 12 15:47:07 volumio1 volumio[1324]: info: Loading plugin "websocket"... Dec 12 15:47:07 volumio1 volumio[1324]: info: Starting Socket.io Server version 1.7.4 Dec 12 15:47:07 volumio1 volumio[1324]: info: Loading plugin "fusiondsp"... Dec 12 15:47:08 volumio1 volumio[1457]: Forking 3 albumart workers Dec 12 15:47:08 volumio1 volumio[1324]: info: Applying required configuration parameters for plugin fusiondsp Dec 12 15:47:09 volumio1 volumio[1324]: info: Loading plugin "podcast"... Dec 12 15:47:11 volumio1 volumio[1324]: info: ControllerPodcast::constructor Dec 12 15:47:11 volumio1 volumio[1324]: info: Loading plugin "backup_restore"... Dec 12 15:47:12 volumio1 systemd[1]: systemd-fsckd.service: Deactivated successfully. Dec 12 15:47:12 volumio1 volumio-remote-updater[746]: [2025-12-12 15:47:12] [connect] Successful connection Dec 12 15:47:13 volumio1 volumio[1324]: info: Applying required configuration parameters for plugin backup_restore Dec 12 15:47:13 volumio1 volumio[1324]: info: Loading plugin "music_services_shield"... Dec 12 15:47:14 volumio1 volumio[1467]: Starting albumart workers Dec 12 15:47:14 volumio1 volumio[1468]: Starting albumart workers Dec 12 15:47:14 volumio1 volumio[1469]: Starting albumart workers Dec 12 15:47:15 volumio1 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Dec 12 15:47:15 volumio1 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 12 15:47:15 volumio1 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 12 15:47:15 volumio1 systemd[1]: systemd-hostnamed.service: Deactivated successfully. Dec 12 15:47:15 volumio1 upmpdcli[1511]: Could not open config: /tmp/upmpdcli.conf Dec 12 15:47:15 volumio1 systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Dec 12 15:47:15 volumio1 systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Dec 12 15:47:15 volumio1 volumio[1324]: info: Applying required configuration parameters for plugin music_services_shield Dec 12 15:47:15 volumio1 volumio[1324]: info: Plugin peppyspectrum is not enabled Dec 12 15:47:15 volumio1 volumio[1324]: info: Loading plugin "randomizer"... Dec 12 15:47:17 volumio1 volumio[1324]: info: Applying required configuration parameters for plugin randomizer Dec 12 15:47:18 volumio1 volumio[1324]: info: Loading plugin "touch_display"... Dec 12 15:47:19 volumio1 volumio[1324]: info: Applying required configuration parameters for plugin touch_display Dec 12 15:47:19 volumio1 volumio[1324]: info: Loading i18n strings for locale sv Dec 12 15:47:19 volumio1 volumio[1324]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Dec 12 15:47:19 volumio1 volumio[1324]: Updating browse sources language Dec 12 15:47:19 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::initPlayerControls Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 15:47:20 volumio1 volumio[1324]: Express server listening on port 3000 Dec 12 15:47:20 volumio1 volumio[1324]: [Metrics] WebUI: 24s 579.11ms Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreStateMachine::resetVolumioState Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreStateMachine::getcurrentVolume Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::volumioRetrievevolume Dec 12 15:47:20 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:20 volumio1 sudo[1557]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 12 15:47:20 volumio1 sudo[1559]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 15:47:20 volumio1 sudo[1557]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:20 volumio1 sudo[1557]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:20 volumio1 sudo[1559]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:20 volumio1 volumio[1324]: info: Volumio Network Manager: Network status updated: 1 Dec 12 15:47:21 volumio1 sudo[1559]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreStateMachine::pushState Dec 12 15:47:21 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreCommandRouter::volumioPushState Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreStateMachine::updateTrackBlock Dec 12 15:47:21 volumio1 volumio[1324]: info: CorePlayQueue::getTrackBlock Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreCommandRouter::volumioRetrievevolume Dec 12 15:47:21 volumio1 volumio[1324]: verbose: New Socket.io Connection to 192.168.2.101:3000 from 192.168.2.100 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Dec 12 15:47:21 volumio1 volumio[1324]: info: Reloading queue from file Dec 12 15:47:21 volumio1 volumio[1324]: verbose: New Socket.io Connection to 192.168.2.101:3000 from 192.168.2.100 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreStateMachine::setRepeat null single undefined Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreStateMachine::pushState Dec 12 15:47:21 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreCommandRouter::volumioPushState Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreStateMachine::setRandom null Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreStateMachine::pushState Dec 12 15:47:21 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreCommandRouter::volumioPushState Dec 12 15:47:21 volumio1 volumio[1324]: info: Setting Device type: Raspberry PI Dec 12 15:47:21 volumio1 volumio[1324]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 12 15:47:21 volumio1 volumio[1324]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03111 Dec 12 15:47:21 volumio1 volumio[1324]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreStateMachine::pushState Dec 12 15:47:21 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreCommandRouter::volumioPushState Dec 12 15:47:21 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:21 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:21 volumio1 volumio[1324]: verbose: New Socket.io Connection to 192.168.2.101:3000 from 192.168.2.100 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 12 15:47:21 volumio1 sudo[1579]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 12 15:47:21 volumio1 sudo[1579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:21 volumio1 volumio[1324]: info: Listing playlists Dec 12 15:47:21 volumio1 volumio[1324]: info: Listing playlists Dec 12 15:47:22 volumio1 volumio[1324]: info: Discovery: adding baf2b384-deac-464a-985d-f56043429001 Dec 12 15:47:22 volumio1 volumio[1324]: info: Discovery: Found device Volumio1 Dec 12 15:47:22 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:22 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:22 volumio1 volumio[1324]: info: Completed loading Core Plugins Dec 12 15:47:22 volumio1 volumio[1324]: info: Preparing to generate the ALSA configuration file Dec 12 15:47:22 volumio1 volumio[1324]: info: Discovery: adding 723cd629-77a6-4d46-b360-70c62cf99719 Dec 12 15:47:22 volumio1 volumio[1324]: info: Discovery: Found device Volumio2 Dec 12 15:47:22 volumio1 volumio[1324]: info: Discovery: Connecting to remote: 192.168.2.120 Dec 12 15:47:22 volumio1 volumio[1324]: info: Discovery: this is already registered, baf2b384-deac-464a-985d-f56043429001 Dec 12 15:47:22 volumio1 volumio[1324]: info: Discovery: Found device Volumio1 Dec 12 15:47:22 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:22 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:22 volumio1 volumio[1324]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Dec 12 15:47:22 volumio1 volumio[1324]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Dec 12 15:47:22 volumio1 volumio[1324]: info: Reading ALSA contributions from plugins. Dec 12 15:47:22 volumio1 volumio[1324]: verbose: New Socket.io Connection to 192.168.2.101:3000 from 192.168.2.100 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 12 15:47:22 volumio1 volumio[1324]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Dec 12 15:47:22 volumio1 volumio[1324]: info: Discovery: Connected to remote: 192.168.2.120 Dec 12 15:47:22 volumio1 sudo[1583]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 12 15:47:22 volumio1 sudo[1583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:22 volumio1 sudo[1585]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 15:47:22 volumio1 sudo[1585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:22 volumio1 sudo[1583]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:22 volumio1 sudo[1585]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:23 volumio1 volumio[1324]: info: Asound.conf file unchanged, so no further update is needed Dec 12 15:47:23 volumio1 volumio[1324]: info: Output device has changed, restarting MPD Dec 12 15:47:23 volumio1 volumio[1324]: info: Output device has changed, restarting Shairport Sync Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:23 volumio1 sudo[1589]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 15:47:23 volumio1 sudo[1589]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:23 volumio1 sudo[1591]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 15:47:23 volumio1 sudo[1589]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:23 volumio1 sudo[1591]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:23 volumio1 volumio[1324]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 15:47:23 volumio1 volumio[1324]: info: ___________ START PLUGINS ___________ Dec 12 15:47:23 volumio1 volumio[1324]: info: ControllerMpd::onStart: Initializing MPD Dec 12 15:47:23 volumio1 volumio[1324]: info: Creating MPD Configuration file Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 15:47:23 volumio1 volumio[1324]: info: [1765550843264] CoreMusicLibrary::Adding element Mediaservrar Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 15:47:23 volumio1 systemd[1]: musicservicesshield.service: Deactivated successfully. Dec 12 15:47:23 volumio1 systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 12 15:47:23 volumio1 systemd[1]: musicservicesshield.service: Consumed 1.093s CPU time. Dec 12 15:47:23 volumio1 systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 12 15:47:23 volumio1 volumio[1324]: info: UPNP Browser: Client initialized successfully Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:23 volumio1 sudo[1600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 15:47:23 volumio1 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 12 15:47:23 volumio1 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 12 15:47:23 volumio1 sudo[1600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:23 volumio1 volumio[1324]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:23 volumio1 sudo[1601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 15:47:23 volumio1 sudo[1601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:23 volumio1 sudo[1601]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:23 volumio1 sudo[1606]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 12 15:47:23 volumio1 sudo[1606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 12 15:47:23 volumio1 sudo[1606]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:23 volumio1 systemd[1]: mpd.service: Deactivated successfully. Dec 12 15:47:23 volumio1 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 12 15:47:23 volumio1 systemd[1]: mpd.socket: Deactivated successfully. Dec 12 15:47:23 volumio1 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 12 15:47:23 volumio1 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 12 15:47:23 volumio1 volumio[1324]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 15:47:23 volumio1 volumio[1324]: info: [1765550843524] CoreMusicLibrary::Adding element Last_100 Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 15:47:23 volumio1 volumio[1324]: info: [1765550843526] CoreMusicLibrary::Adding element Webradio Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 15:47:23 volumio1 volumio[1324]: info: Initializing BBC Radios Dec 12 15:47:23 volumio1 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 12 15:47:23 volumio1 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 12 15:47:23 volumio1 sudo[1620]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 12 15:47:23 volumio1 sudo[1620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 12 15:47:23 volumio1 sudo[1629]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 12 15:47:23 volumio1 sudo[1620]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:23 volumio1 volumio[1324]: info: Creating Spotify config file Dec 12 15:47:23 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:25 volumio1 volumio[1324]: info: [now-playing] ConfigUpdater: config is up to date. Dec 12 15:47:25 volumio1 volumio[1324]: info: FusionDsp - CamillaDSP binary found. Dec 12 15:47:25 volumio1 volumio[1324]: info: Loading i18n strings for locale sv Dec 12 15:47:25 volumio1 volumio[1324]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Dec 12 15:47:25 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 12 15:47:25 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:25 volumio1 volumio[1324]: info: FusionDsp - mixtype--------------------- Software Dec 12 15:47:25 volumio1 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 12 15:47:25 volumio1 volumio[1324]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 15:47:25 volumio1 volumio[1324]: info: [1765550845605] CoreMusicLibrary::Adding element Podcast Dec 12 15:47:25 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 15:47:25 volumio1 volumio[1324]: Cannot find translation for source Podcast Dec 12 15:47:26 volumio1 volumio[1324]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 15:47:26 volumio1 volumio[1324]: info: [1765550846492] CoreMusicLibrary::Adding element Randomizer Dec 12 15:47:26 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 15:47:26 volumio1 volumio[1324]: Cannot find translation for source Podcast Dec 12 15:47:26 volumio1 volumio[1324]: Cannot find translation for source Randomizer Dec 12 15:47:26 volumio1 volumio[1324]: info: Loading i18n strings for locale sv Dec 12 15:47:26 volumio1 volumio[1324]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Dec 12 15:47:26 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 15:47:26 volumio1 volumio[1324]: info: Volumio Calling Home Dec 12 15:47:26 volumio1 systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 12 15:47:26 volumio1 systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 12 15:47:26 volumio1 sudo[1679]: volumio : PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh Dec 12 15:47:26 volumio1 sudo[1679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:26 volumio1 sudo[1687]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /data/volumiokioskextensions/IframeKeyboardBridge Dec 12 15:47:26 volumio1 sudo[1687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:27 volumio1 sudo[1687]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:27 volumio1 volumio[1324]: info: Preparing to generate the ALSA configuration file Dec 12 15:47:27 volumio1 volumio-remote-updater[746]: [2025-12-12 15:47:27] [connect] Successful connection Dec 12 15:47:27 volumio1 sudo[1706]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Dec 12 15:47:27 volumio1 sudo[1706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:27 volumio1 sudo[1706]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:27 volumio1 sudo[1708]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Dec 12 15:47:27 volumio1 sudo[1708]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:27 volumio1 sudo[1711]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 12 15:47:27 volumio1 sudo[1711]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:27 volumio1 systemd[1]: Reloading. Dec 12 15:47:28 volumio1 mpd[1630]: 2025-12-12T15:47:28 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 12 15:47:28 volumio1 systemd[1]: /etc/systemd/system/musicservicesshield.service:14: Failed to parse output specifier, ignoring: jouurnal Dec 12 15:47:28 volumio1 volumio[1324]: info: [now-playing] App is listening on port 4004. Dec 12 15:47:28 volumio1 volumio[1324]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Dec 12 15:47:29 volumio1 systemd[1]: Started mpd.service - Music Player Daemon. Dec 12 15:47:29 volumio1 sudo[1600]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:29 volumio1 sudo[1711]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:29 volumio1 sudo[1591]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:29 volumio1 volumio[1324]: info: camilladsp service started and running in background, instance 1 Dec 12 15:47:29 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:29 volumio1 systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 12 15:47:29 volumio1 systemd[1]: Reloading. Dec 12 15:47:29 volumio1 volumio[1324]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 176400 192000 <-AAAAAAAAAAAAA Dec 12 15:47:29 volumio1 volumio[1324]: info: FusionDsp loaded Dec 12 15:47:29 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 12 15:47:29 volumio1 volumio[1324]: error: FusionDsp - Socket connection not established Dec 12 15:47:29 volumio1 volumio[1324]: info: FusionDsp - Reporting Fusion DSP Enabled Dec 12 15:47:29 volumio1 volumio[1324]: info: Adding Signal Path Element [object Object] Dec 12 15:47:29 volumio1 volumio[1324]: info: Adding fusiondspeq DSP Signal Path Element Dec 12 15:47:29 volumio1 volumio[1324]: info: FusionDsp - ---- installed callbackRead Dec 12 15:47:29 volumio1 volumio[1324]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 12 15:47:29 volumio1 sudo[1758]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Dec 12 15:47:29 volumio1 sudo[1758]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:30 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Dec 12 15:47:30 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:30 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:30 volumio1 systemd[1]: /etc/systemd/system/musicservicesshield.service:14: Failed to parse output specifier, ignoring: jouurnal Dec 12 15:47:30 volumio1 volumio[1324]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Dec 12 15:47:30 volumio1 volumio[1324]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Dec 12 15:47:30 volumio1 volumio[1324]: info: Reading ALSA contributions from plugins. Dec 12 15:47:30 volumio1 volumio[1324]: info: touch_display: No backlight interface detected. Dec 12 15:47:30 volumio1 bash[1785]: cset: --> shielding system active with Dec 12 15:47:30 volumio1 bash[1785]: cset: "system" cpuset of CPUSPEC(1-3) with 153 tasks running Dec 12 15:47:30 volumio1 bash[1785]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Dec 12 15:47:30 volumio1 systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 12 15:47:30 volumio1 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Dec 12 15:47:30 volumio1 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 12 15:47:30 volumio1 sudo[1708]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:30 volumio1 volumio[1324]: info: touch_display: systemctl daemon-reload succeeded. Dec 12 15:47:30 volumio1 volumio[1324]: info: touch_display: systemctl stop getty@tty1.service succeeded. Dec 12 15:47:30 volumio1 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 12 15:47:30 volumio1 volumio[1324]: info: MPD Permissions set Dec 12 15:47:30 volumio1 systemd[1]: Started fusiondsp.service - FusionDsp Daemon. Dec 12 15:47:30 volumio1 sudo[1579]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:30 volumio1 volumio[1324]: info: MPD Permissions set Dec 12 15:47:30 volumio1 sudo[1758]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:30 volumio1 sudo[1796]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Dec 12 15:47:30 volumio1 sudo[1796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:31 volumio1 sudo[1800]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/cp -r /data/plugins/user_interface/touch_display/iframe_keyboard_bridge/content.js /data/plugins/user_interface/touch_display/iframe_keyboard_bridge/manifest.json /data/volumiokioskextensions/IframeKeyboardBridge/ Dec 12 15:47:31 volumio1 volumio[1324]: verbose: New Socket.io Connection to 192.168.2.101 from 192.168.2.172 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.6 Safari/605.1.15 Engine version: 3 Transport: polling Total Clients: 6 Dec 12 15:47:31 volumio1 sudo[1800]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:31 volumio1 volumio-remote-updater[746]: [2025-12-12 15:47:31] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765550847 101 Dec 12 15:47:31 volumio1 volumio[1324]: 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: 7 Dec 12 15:47:31 volumio1 volumio[1324]: error: FusionDsp - Reload WebSocket error: [object Object] Dec 12 15:47:31 volumio1 sudo[1800]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:31 volumio1 systemd[1]: Started volumio-kiosk.service - Volumio Kiosk. Dec 12 15:47:31 volumio1 sudo[1796]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:31 volumio1 volumio[1324]: info: Upmpdcli Daemon Started Dec 12 15:47:31 volumio1 volumio[1324]: info: touch_display: systemctl disable getty@tty1.service succeeded. Dec 12 15:47:31 volumio1 volumio[1324]: info: Volumio called home Dec 12 15:47:31 volumio1 volumio[1324]: info: Spotify config file written Dec 12 15:47:31 volumio1 startx[1847]: X.Org X Server 1.21.1.7 Dec 12 15:47:31 volumio1 startx[1847]: X Protocol Version 11, Revision 0 Dec 12 15:47:31 volumio1 startx[1847]: Current Operating System: Linux volumio1 6.12.47-v7l+ #1904 SMP Mon Sep 15 13:08:10 BST 2025 armv7l Dec 12 15:47:31 volumio1 startx[1847]: 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:3840x2160M@30D numa=fake=1 system_heap.max_order=0 smsc95xx.macaddr=DC:A6:32:52:84:FF 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=cc40bcae-8e5b-4465-a1d2-022efc5b5ed0 imgfile=/volumio_current.sqsh bootpart=UUID=CB70-A442 datapart=UUID=c824eb1e-6c2b-4cc1-a030-f182645bbe25 uuidconfig=cmdline.txt rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Dec 12 15:47:31 volumio1 startx[1847]: xorg-server 2:21.1.7-3+rpt3+deb12u10 (https://www.debian.org/support) Dec 12 15:47:31 volumio1 startx[1847]: Current version of pixman: 0.44.0 Dec 12 15:47:31 volumio1 startx[1847]: Before reporting problems, check http://wiki.x.org Dec 12 15:47:31 volumio1 startx[1847]: to make sure that you have the latest version. Dec 12 15:47:31 volumio1 startx[1847]: Markers: (--) probed, (**) from config file, (==) default setting, Dec 12 15:47:31 volumio1 startx[1847]: (++) from command line, (!!) notice, (II) informational, Dec 12 15:47:31 volumio1 startx[1847]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Dec 12 15:47:31 volumio1 startx[1847]: (==) Log file: "/var/log/Xorg.0.log", Time: Fri Dec 12 15:47:31 2025 Dec 12 15:47:31 volumio1 startx[1847]: (==) Using config directory: "/etc/X11/xorg.conf.d" Dec 12 15:47:31 volumio1 startx[1847]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Dec 12 15:47:31 volumio1 sudo[1850]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 12 15:47:31 volumio1 sudo[1850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:31 volumio1 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. Dec 12 15:47:31 volumio1 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. Dec 12 15:47:32 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:32 volumio1 go-librespot[1853]: go-librespot daemon starting... Dec 12 15:47:32 volumio1 sudo[1850]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:32 volumio1 go-librespot[1854]: time="2025-12-12T15:47:32+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 15:47:32 volumio1 go-librespot[1854]: time="2025-12-12T15:47:32+01:00" level=debug msg="app state loaded" Dec 12 15:47:32 volumio1 go-librespot[1854]: time="2025-12-12T15:47:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 15:47:32 volumio1 go-librespot[1854]: time="2025-12-12T15:47:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 12 15:47:32 volumio1 go-librespot[1854]: time="2025-12-12T15:47:32+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 12 15:47:32 volumio1 go-librespot[1854]: time="2025-12-12T15:47:32+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 12 15:47:32 volumio1 go-librespot[1854]: time="2025-12-12T15:47:32+01:00" level=info msg="zeroconf server listening on port 34623" Dec 12 15:47:33 volumio1 go-librespot[1854]: time="2025-12-12T15:47:33+01:00" level=debug msg="obtained new client token: AACBH3826+cOPSsSYy/ZwQ82B0vPnR4j0QGD47nFdYfcyjDZWmu9twhJZP+2GUSglyhmx1SYdn/kVJDMZU4pUmpeF9TDYpKXDs/k7Pg328fWAZ1vUO8JmmnvlApymseI29IoIjxySYN2dO+4FhjtuZFR2OKA/JJDaTL5L4N7Maqx6SbogjreiRgOI1uXiMR0K3C48BzYn3BZbB4RzUFjKdmWP7GJX1xI+uGxdedcOspYMU1McyM7Ue0S+g==" Dec 12 15:47:33 volumio1 go-librespot[1854]: time="2025-12-12T15:47:33+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 15:47:33 volumio1 go-librespot[1854]: time="2025-12-12T15:47:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 12 15:47:33 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 15:47:33 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 15:47:33 volumio1 sudo[1679]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:33 volumio1 volumio[1324]: error: MPD error: The expression evaluated to a falsy value: Dec 12 15:47:33 volumio1 volumio[1324]: assert.ok(self.idling) Dec 12 15:47:33 volumio1 volumio[1324]: error: The expression evaluated to a falsy value: Dec 12 15:47:33 volumio1 volumio[1324]: assert.ok(self.idling) Dec 12 15:47:34 volumio1 volumio[1324]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Dec 12 15:47:34 volumio1 volumio[1324]: info: touch_display: Volumio Kiosk started. Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:34 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:34 volumio1 volumio[1324]: info: touch_display: IframeKeyboardBridge extension installed successfully Dec 12 15:47:34 volumio1 volumio[1324]: info: MPD running with PID1630 Dec 12 15:47:34 volumio1 volumio[1324]: ,establishing connection Dec 12 15:47:34 volumio1 sudo[1896]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 15:47:34 volumio1 sudo[1896]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 sudo[1910]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 15:47:34 volumio1 sudo[1910]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:34 volumio1 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:34 volumio1 mpd_monitor.sh[1928]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 15:47:34 volumio1 sudo[1896]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:34 volumio1 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 12 15:47:34 volumio1 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 12 15:47:34 volumio1 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 12 15:47:34 volumio1 mpd_monitor.sh[1941]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 15:47:34 volumio1 sudo[1910]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:34 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:35 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:35 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:35 volumio1 volumio[1324]: info: No need to fix Spotify hosts Dec 12 15:47:35 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:35 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:35 volumio1 volumio[1324]: error: updateQueue error: null Dec 12 15:47:35 volumio1 volumio[1324]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 12 15:47:35 volumio1 volumio[1324]: info: touch_display: X display number found: 0 Dec 12 15:47:35 volumio1 volumio[1324]: info: Completed starting Core Plugins Dec 12 15:47:35 volumio1 volumio[1324]: info: ------------------------------------------- Dec 12 15:47:35 volumio1 volumio[1324]: info: ----- MyVolumio plugins startup ---- Dec 12 15:47:35 volumio1 volumio[1324]: info: ------------------------------------------- Dec 12 15:47:35 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 12 15:47:35 volumio1 sudo[1961]: volumio : PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh Dec 12 15:47:35 volumio1 sudo[1961]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:35 volumio1 volumio[1324]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Dec 12 15:47:35 volumio1 systemd[1]: Reloading. Dec 12 15:47:35 volumio1 volumio[1324]: info: Successfully started MPD Monitor Dec 12 15:47:35 volumio1 volumio[1324]: info: Successfully started MPD Monitor Dec 12 15:47:36 volumio1 volumio[1324]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Dec 12 15:47:36 volumio1 volumio[1324]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 12 15:47:36 volumio1 volumio[1324]: SPOTIFY: BQB8hwKqEVaPYqx-UZKcSp8T_x0-kTYpQU2X429WCTrdKNjR7F9YxgVAZk_jRhT0gHgDUYcaJZNpyH6Cc8LjXO6ogodEisbGObwqjlsiZegF9Kkjz7oYDS1_bDFt3fFADa6tp_VC7td3hNoVncexVxm_IdenBzUVIZeIZdxG_QRTdZnWU0x1CjgS7Q8OqZPHLxeGOoz6VATEb2QTVxUPVbetIYeKgI3EL9RMW5dErO3DQVWQ33540-99_Fqu8y3HEECG1WuGJ1vw1UKepEvkNAv_F1hae80 Dec 12 15:47:36 volumio1 volumio[1324]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 12 15:47:36 volumio1 volumio[1324]: info: New Spotify access token = BQB8hwKqEVaPYqx-UZKcSp8T_x0-kTYpQU2X429WCTrdKNjR7F9YxgVAZk_jRhT0gHgDUYcaJZNpyH6Cc8LjXO6ogodEisbGObwqjlsiZegF9Kkjz7oYDS1_bDFt3fFADa6tp_VC7td3hNoVncexVxm_IdenBzUVIZeIZdxG_QRTdZnWU0x1CjgS7Q8OqZPHLxeGOoz6VATEb2QTVxUPVbetIYeKgI3EL9RMW5dErO3DQVWQ33540-99_Fqu8y3HEECG1WuGJ1vw1UKepEvkNAv_F1hae80 Dec 12 15:47:36 volumio1 sudo[1995]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Dec 12 15:47:36 volumio1 sudo[1995]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:36 volumio1 sudo[2000]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Dec 12 15:47:36 volumio1 volumio[1324]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 12 15:47:36 volumio1 sudo[2000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:36 volumio1 sudo[1995]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:36 volumio1 sudo[2000]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:36 volumio1 volumio[1324]: error: updateQueue error: null Dec 12 15:47:36 volumio1 systemd[1]: /etc/systemd/system/musicservicesshield.service:14: Failed to parse output specifier, ignoring: jouurnal Dec 12 15:47:36 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 12 15:47:36 volumio1 volumio[1324]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Dec 12 15:47:36 volumio1 volumio[1324]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Dec 12 15:47:37 volumio1 volumio[1324]: info: Starting Shairport Sync Dec 12 15:47:37 volumio1 volumio[1324]: info: Starting Shairport Sync Dec 12 15:47:37 volumio1 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. Dec 12 15:47:37 volumio1 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. Dec 12 15:47:37 volumio1 volumio[1324]: info: Starting Shairport Sync Dec 12 15:47:37 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 12 15:47:37 volumio1 sudo[2017]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 15:47:37 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:37 volumio1 sudo[2019]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 15:47:37 volumio1 sudo[2019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:37 volumio1 sudo[2017]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:37 volumio1 sudo[2023]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 15:47:37 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:37 volumio1 go-librespot[2021]: go-librespot daemon starting... Dec 12 15:47:37 volumio1 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 15:47:37 volumio1 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 15:47:37 volumio1 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 15:47:37 volumio1 systemd[1]: shairport-sync.service: Consumed 1.599s CPU time. Dec 12 15:47:37 volumio1 sudo[1961]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:37 volumio1 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 15:47:37 volumio1 sudo[2019]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=debug msg="app state loaded" Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 15:47:37 volumio1 sudo[2023]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:37 volumio1 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 15:47:37 volumio1 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 15:47:37 volumio1 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 15:47:37 volumio1 volumio[1324]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=info msg="zeroconf server listening on port 41471" Dec 12 15:47:37 volumio1 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 15:47:37 volumio1 volumio[1324]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Dec 12 15:47:37 volumio1 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 15:47:37 volumio1 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 15:47:37 volumio1 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 15:47:37 volumio1 sudo[2017]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:37 volumio1 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=debug msg="obtained new client token: AABAuKBgr0wkkLCCXOrffAzg7x31tzcn/32N29D5nQMnNTtJt8gJFZRg10y+3qX9NGFTMWWah5+gbg4VhZZBYWG18jSWUa4rshDN6xAd2oKtBIX17qRlF0k8wEyOJsF3ruE9zMXfch73bquQLnNWhEbXFq++0X0cKFI8jr2mA5jJ3Fgt3RQb/JdkJNaxDKYWwNAFd3iEsZ8VUDfPIExojQeFI49nrOGfZmK+61SiBnxtws61RwnP5KaNLQ==" Dec 12 15:47:37 volumio1 sudo[2023]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 15:47:37 volumio1 go-librespot[2025]: time="2025-12-12T15:47:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 12 15:47:37 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 15:47:37 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:38 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:38 volumio1 volumio[1324]: info: Shairport-Sync Started Dec 12 15:47:38 volumio1 volumio[1324]: Error adding Membership: Error: addMembership EINVAL Dec 12 15:47:38 volumio1 volumio[1324]: info: Shairport-Sync Started Dec 12 15:47:38 volumio1 volumio[1324]: info: succeeded Dec 12 15:47:38 volumio1 volumio[1324]: info: touch_display: X display number found: 0 Dec 12 15:47:38 volumio1 volumio[1324]: info: Asound.conf file unchanged, so no further update is needed Dec 12 15:47:38 volumio1 volumio[1324]: info: Output device has changed, restarting MPD Dec 12 15:47:38 volumio1 volumio[1324]: info: Output device has changed, restarting Shairport Sync Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:38 volumio1 sudo[2078]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 15:47:38 volumio1 sudo[2078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:38 volumio1 sudo[2080]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 15:47:38 volumio1 sudo[2078]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:38 volumio1 sudo[2080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:38 volumio1 volumio[1324]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetVisibleSources Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 15:47:38 volumio1 systemd[1]: musicservicesshield.service: Deactivated successfully. Dec 12 15:47:38 volumio1 systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 12 15:47:38 volumio1 systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 12 15:47:38 volumio1 systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:38 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 12 15:47:38 volumio1 volumio[1324]: info: Received Get System Info Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 12 15:47:38 volumio1 volumio[1324]: info: Discovery: Getting this device information Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:38 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 12 15:47:38 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:38 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:39 volumio1 systemd[1]: mpd.service: Deactivated successfully. Dec 12 15:47:39 volumio1 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 12 15:47:39 volumio1 systemd[1]: mpd.service: Consumed 3.300s CPU time. Dec 12 15:47:39 volumio1 systemd[1]: mpd.socket: Deactivated successfully. Dec 12 15:47:39 volumio1 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 12 15:47:39 volumio1 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 12 15:47:39 volumio1 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 12 15:47:39 volumio1 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 12 15:47:39 volumio1 volumio[1324]: info: Listing playlists Dec 12 15:47:39 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:39 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:39 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 12 15:47:39 volumio1 volumio[1324]: info: Received Get System Info Dec 12 15:47:39 volumio1 sudo[2092]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 12 15:47:39 volumio1 sudo[2092]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 12 15:47:39 volumio1 sudo[2092]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:39 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 12 15:47:39 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 12 15:47:39 volumio1 volumio[1324]: info: Discovery: Getting this device information Dec 12 15:47:39 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:39 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:39 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 12 15:47:39 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 12 15:47:39 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 12 15:47:39 volumio1 volumio[1324]: info: Shairport-Sync Started Dec 12 15:47:39 volumio1 volumio[1324]: error: MPD error: Error: write EPIPE Dec 12 15:47:39 volumio1 volumio[1324]: error: write EPIPE {"code":"EPIPE","errno":-32,"syscall":"write"} Dec 12 15:47:39 volumio1 volumio[1324]: info: go-librespot daemon successfully initialized Dec 12 15:47:40 volumio1 volumio[1324]: info: MPD Permissions set Dec 12 15:47:41 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 12 15:47:41 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:41 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:41 volumio1 go-librespot[2131]: go-librespot daemon starting... Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=debug msg="app state loaded" Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 15:47:41 volumio1 mpd[2094]: 2025-12-12T15:47:41 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=info msg="zeroconf server listening on port 43795" Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=debug msg="obtained new client token: AADo8yvDtyH1LJiNGVYAVjq2qDHh/FcwoHxDURtyaHiQQvGXOe6rN1Hk/fgyGZBwyogKzLpILUZN7ALVP0PNjeS2jvWDNL8fa6KbOErJ/nt1eWN2KE0tCNDEwCpXAF96e1teb6OJbzSbjoxXUR5sGFtBl0Jsf0IDx74VGkn+8ZtjzGm6L7kDdCr3Oh0KynXNWDYA1L6kMAPPd68YYgwh23lRsVa5f0TKiMj8G659KUazcGup2TWHMe271A==" Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 15:47:41 volumio1 go-librespot[2138]: time="2025-12-12T15:47:41+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 12 15:47:41 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 15:47:41 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 systemd[1]: Started mpd.service - Music Player Daemon. Dec 12 15:47:41 volumio1 sudo[2080]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:41 volumio1 systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 12 15:47:41 volumio1 volumio[1324]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 12 15:47:41 volumio1 volumio[1324]: info: Received Get System Version Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 15:47:41 volumio1 volumio[1324]: info: Received Get System Info Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 12 15:47:41 volumio1 volumio[1324]: info: Discovery: Getting this device information Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:41 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 12 15:47:41 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 12 15:47:41 volumio1 volumio[1324]: info: touch_display: Setting screensaver timeout to 0 seconds. Dec 12 15:47:42 volumio1 volumio[1324]: info: Starting Shairport Sync Dec 12 15:47:42 volumio1 sudo[2190]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 15:47:42 volumio1 sudo[2190]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:42 volumio1 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 15:47:42 volumio1 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 15:47:42 volumio1 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 15:47:42 volumio1 systemd[1]: shairport-sync.service: Consumed 1.125s CPU time. Dec 12 15:47:42 volumio1 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 15:47:43 volumio1 sudo[2190]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:43 volumio1 bash[2205]: cset: --> shielding system active with Dec 12 15:47:43 volumio1 bash[2205]: cset: "system" cpuset of CPUSPEC(1-3) with 241 tasks running Dec 12 15:47:43 volumio1 bash[2205]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Dec 12 15:47:43 volumio1 systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 12 15:47:43 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 12 15:47:43 volumio1 volumio[1324]: info: Initializing connection to go-librespot Websocket Dec 12 15:47:43 volumio1 volumio[1324]: error: updateQueue error: null Dec 12 15:47:43 volumio1 volumio[1324]: info: Shairport-Sync Started Dec 12 15:47:44 volumio1 volumio[1324]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 15:47:44 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 12 15:47:44 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:44 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:44 volumio1 go-librespot[2231]: go-librespot daemon starting... Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=debug msg="app state loaded" Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 15:47:44 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 12 15:47:44 volumio1 volumio[1324]: info: Discovery: Getting this device information Dec 12 15:47:44 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 12 15:47:44 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:44 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=info msg="zeroconf server listening on port 45343" Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=debug msg="obtained new client token: AAAroKvbx5gl8ZHt6CxEVEKmF+aIDLikRMgp6Ea03/K3XokBG1NMSH8g5AwsxgxQLwjZK21iY2egycPeEHNlZBd9HCrlp09c4VGEeSwm5C+F+nRFu+ml1X3raaxecVtbCRgtWFEMqi1YVkhNthGyQpyDq32ptWOqizm5i4NCSy5dOiMc+TWz+o2PQCbL9d02TL0nDxZ4gfqKVxukcKg6WqNBNFLYeV6fhCNjYgknz+AoVxHxD/NIrAGZ+Q==" Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 15:47:44 volumio1 go-librespot[2232]: time="2025-12-12T15:47:44+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 12 15:47:44 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 15:47:44 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 15:47:45 volumio1 volumio[1324]: SPOTIFY: User informations: {"country":"SE","display_name":"gudden","email":"gudden@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/gudden"},"followers":{"href":null,"total":3},"href":"https://api.spotify.com/v1/users/gudden","id":"gudden","images":[],"product":"premium","type":"user","uri":"spotify:user:gudden"} Dec 12 15:47:45 volumio1 volumio[1324]: info: Spotify Successfully logged in Dec 12 15:47:45 volumio1 volumio[1324]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 15:47:45 volumio1 volumio[1324]: info: [1765550865182] CoreMusicLibrary::Adding element Spotify Dec 12 15:47:45 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 15:47:45 volumio1 volumio[1324]: Cannot find translation for source Podcast Dec 12 15:47:45 volumio1 volumio[1324]: Cannot find translation for source Randomizer Dec 12 15:47:45 volumio1 volumio[1324]: Cannot find translation for source Spotify Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 12 15:47:45 volumio1 volumio[1324]: info: Adding plugin bluetooth to MyMusic Plugins Dec 12 15:47:45 volumio1 volumio[1324]: info: Adding plugin multiroom to MyMusic Plugins Dec 12 15:47:45 volumio1 volumio[1324]: info: Adding plugin metavolumio to MyMusic Plugins Dec 12 15:47:45 volumio1 volumio[1324]: info: Adding plugin cd_controller to MyMusic Plugins Dec 12 15:47:45 volumio1 volumio[1324]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 12 15:47:45 volumio1 volumio[1324]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 12 15:47:45 volumio1 volumio[1324]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 12 15:47:45 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 12 15:47:48 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 12 15:47:48 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:48 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 15:47:48 volumio1 go-librespot[2241]: go-librespot daemon starting... Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="app state loaded" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=info msg="zeroconf server listening on port 44999" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="obtained new client token: AAANpCU7c4n/QMPWEdH6owKUejF9kklXs593NO2HwnVKOrUKzPhSe0WdrNFLfjxoa4eV654pyhlwbKekx7beAwQjRsKmLEcCxGfXhpCy7y/Lot3CN5+qjOzyp0VD+JgRhHuPdIa4sYBgLPpyKLywo44o3IFQLo2IwpyNvj+qXuPACPnEIco2gDZVCeoFN8ggyoByJKkGNMbdXMaHcPDMRihvHlCmkURU2F9MFL4fUB9WiluYEThluZbwAg==" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="completed keyexchange" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="completed challenge" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=info msg="authenticated AP" username="gu**en" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=info msg="authenticated Login5" username="gu**en" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="initializing zeroconf session" username="gu**en" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="dealer connection opened" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=trace msg="starting accesspoint recv loop" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=trace msg="starting dealer recv loop" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=trace msg="received accesspoint ping" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="received connection id: ZWI5YjdmNjktYWQz...MDE3RjdDMTMyMA==" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=trace msg="received accesspoint pong ack" Dec 12 15:47:48 volumio1 go-librespot[2242]: time="2025-12-12T15:47:48+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 12 15:47:51 volumio1 volumio[1324]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 12 15:47:51 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 12 15:47:51 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:51 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:51 volumio1 volumio[1324]: info: Starting MyVolumio Remote Streaming Endpoints Dec 12 15:47:51 volumio1 volumio[1324]: info: MyVolumio login type: Token Dec 12 15:47:51 volumio1 volumio[1324]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 12 15:47:51 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 12 15:47:55 volumio1 upmpdcli[2266]: writing RSA key Dec 12 15:47:56 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 12 15:47:56 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 12 15:47:56 volumio1 volumio[1324]: info: Streaming services startup Dec 12 15:47:56 volumio1 volumio[1324]: info: Starting Streaming Daemon Dec 12 15:47:56 volumio1 volumio[1324]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 12 15:47:56 volumio1 sudo[2274]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 12 15:47:56 volumio1 sudo[2274]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:56 volumio1 sudo[2274]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:56 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:56 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:56 volumio1 volumio[1324]: info: Initializing connection to go-librespot Websocket Dec 12 15:47:56 volumio1 sudo[2281]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 15:47:56 volumio1 sudo[2281]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 15:47:56 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 15:47:56 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 15:47:56 volumio1 volumio[1324]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 12 15:47:56 volumio1 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 12 15:47:56 volumio1 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 12 15:47:56 volumio1 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 12 15:47:56 volumio1 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 12 15:47:56 volumio1 mpd_monitor.sh[2286]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 15:47:56 volumio1 sudo[2281]: pam_unix(sudo:session): session closed for user root Dec 12 15:47:56 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:56 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:56 volumio1 volumio[1324]: error: Cannot start Volumio Streaming Daemon Dec 12 15:47:56 volumio1 volumio[1324]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 12 15:47:56 volumio1 volumio[1324]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 12 15:47:56 volumio1 volumio[1324]: info: Listing playlists Dec 12 15:47:56 volumio1 volumio[1324]: info: Listing playlists Dec 12 15:47:56 volumio1 go-librespot[2242]: time="2025-12-12T15:47:56+01:00" level=debug msg="new websocket client" Dec 12 15:47:56 volumio1 volumio[1324]: info: Successfully started MPD Monitor Dec 12 15:47:57 volumio1 volumio[1324]: info: Connection to go-librespot Websocket established Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="handling transfer player command from f399d42d9f85297b79ce72b49a517bb96f76a061" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="resolved context of track" uri="spotify:user:gudden:collection" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=trace msg="fetched new page 0 with 696 items (list: 696)" uri="spotify:user:gudden:collection" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="shuffled context with seed 17341558790228038501 (len: 696, keep: 501)" uri="spotify:user:gudden:collection" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="loading track (paused: false, position: 142756ms)" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=trace msg="emitting websocket event: will_play" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 310" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="selected format OGG_VORBIS_320 (9a1ccea5e8b9e9254dea567b2603bd53b1c9bb1e)" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="requested aes key for file 9a1ccea5e8b9e9254dea567b2603bd53b1c9bb1e, gid: 1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1329" Dec 12 15:47:57 volumio1 volumio[1324]: error: MyVolumio Custom Token format not valid, refreshing it Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:57 volumio1 volumio[1324]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:user:gudden:collection","uri":"spotify:track:1PEjhR1CCdINF8TyM5s8LX","play_origin":"collection/songs"}} Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="fetched first chunk of 14, total size is 6988542 bytes" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:57 volumio1 go-librespot[2242]: time="2025-12-12T15:47:57+01:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="fetched chunk 9/13, size: 524288" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=trace msg="seek to 142756ms (diff: 112ms, samples: 6295539, bytes: 5202237)" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="created new output device" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="fetched chunk 12/13, size: 524288" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="fetched chunk 10/13, size: 524288" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="fetched chunk 11/13, size: 524288" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=info msg="loaded track \"That's How I'm Feeling\" (paused: false, position: 142756ms, duration: 191813ms, prefetched: false)" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=trace msg="scheduling prefetch in 19s" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=trace msg="emitting websocket event: metadata" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=trace msg="emitting websocket event: active" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="sending successful reply for dealer request" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=trace msg="emitting websocket event: playing" Dec 12 15:47:58 volumio1 go-librespot[2242]: time="2025-12-12T15:47:58+01:00" level=debug msg="fetched chunk 13/13, size: 172798" uri="spotify:track:1PEjhR1CCdINF8TyM5s8LX" Dec 12 15:47:58 volumio1 volumio[1324]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Dec 12 15:47:58 volumio1 volumio[1324]: info: FusionDsp - ---- read samplerate from file: 44100 Dec 12 15:47:58 volumio1 volumio[1324]: info: camilladsp stopping service pid 1741... Dec 12 15:47:58 volumio1 kernel: xhci_hcd 0000:01:00.0: ERROR Transfer event for disabled endpoint slot 2 ep 9 Dec 12 15:47:58 volumio1 kernel: xhci_hcd 0000:01:00.0: @000000040cd08be0 00000000 00000000 0e000000 020a8001 Dec 12 15:47:59 volumio1 volumio[1324]: grep: /proc/1741/cmdline: binary file matches Dec 12 15:47:59 volumio1 volumio[1324]: grep: /proc/1741/cmdline: binary file matches Dec 12 15:47:59 volumio1 volumio[1324]: grep: /proc/1741/cmdline: binary file matches Dec 12 15:47:59 volumio1 volumio[1324]: info: camilladsp service terminated, instance 1 Dec 12 15:47:59 volumio1 volumio[1324]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 12 15:47:59 volumio1 volumio[1324]: info: camilladsp service started and running in background, instance 1 Dec 12 15:47:59 volumio1 volumio[1324]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1PEjhR1CCdINF8TyM5s8LX","name":"That's How I'm Feeling","artist_names":["Jack White"],"album_name":"No Name","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024e0e873e5b2878a26796cbdd","position":142756,"duration":191813,"release_date":"year:2024 month:8 day:2","track_number":3,"disc_number":1}} Dec 12 15:47:59 volumio1 volumio[1324]: SPOTIFY: received: {"type":"active","data":null} Dec 12 15:47:59 volumio1 volumio[1324]: info: Aligning Spotify Volume to Volumio Volume Dec 12 15:47:59 volumio1 volumio[1324]: info: CoreCommandRouter::volumioGetState Dec 12 15:47:59 volumio1 volumio[1324]: info: CorePlayQueue::getTrack 0 Dec 12 15:47:59 volumio1 volumio[1324]: info: Setting Spotify Volume from Volumio: 33 Dec 12 15:47:59 volumio1 volumio[1324]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:user:gudden:collection","uri":"spotify:track:1PEjhR1CCdINF8TyM5s8LX","resume":false,"play_origin":"collection/songs"}} Dec 12 15:47:59 volumio1 volumio[1324]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 15:47:59 volumio1 volumio[1324]: TypeError: Cannot read properties of undefined (reading 'service') Dec 12 15:47:59 volumio1 volumio[1324]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 12 15:47:59 volumio1 volumio[1324]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Dec 12 15:47:59 volumio1 volumio[1324]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 12 15:47:59 volumio1 volumio[1324]: at WebSocket.emit (node:events:514:28) Dec 12 15:47:59 volumio1 volumio[1324]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 12 15:47:59 volumio1 volumio[1324]: at Receiver.emit (node:events:514:28) Dec 12 15:47:59 volumio1 volumio[1324]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 12 15:47:59 volumio1 volumio[1324]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 12 15:47:59 volumio1 volumio[1324]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 12 15:47:59 volumio1 volumio[1324]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 12 15:47:59 volumio1 volumio[1324]: at writeOrBuffer (node:internal/streams/writable:399:12) Dec 12 15:47:59 volumio1 volumio[1324]: at _write (node:internal/streams/writable:340:10) Dec 12 15:47:59 volumio1 volumio[1324]: at Writable.write (node:internal/streams/writable:344:10) Dec 12 15:47:59 volumio1 volumio[1324]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 12 15:47:59 volumio1 volumio[1324]: at Socket.emit (node:events:514:28) Dec 12 15:47:59 volumio1 volumio[1324]: at addChunk (node:internal/streams/readable:343:12) Dec 12 15:47:59 volumio1 volumio[1324]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 15:48:03 volumio1 sudo[2334]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-12 15:47' Dec 12 15:48:03 volumio1 sudo[2334]: 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="140c1549b54b48087be58e6d122fe2155a57ac20" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="2f25e1a98e53e2dbc4f3878604e250b0379f3ea4" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 11 18:08:21 UTC 2025" VOLUMIO_VERSION="4.080" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="c84e943fcb997d76b00264035c7241c7"