Dec 29 16:01:04 garage ntpd[975]: CLOCK: time stepped by 12124.640375 Dec 29 16:01:04 garage ntpd[975]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Dec 29 16:01:04 garage volumio[1226]: info: MYVOLUMIO Environment detected Dec 29 16:01:05 garage volumio[1226]: info: Plugin folders cleanup Dec 29 16:01:05 garage volumio[1226]: info: Scanning into folder /volumio/app/plugins/ Dec 29 16:01:05 garage volumio[1226]: info: Scanning category audio_interface Dec 29 16:01:05 garage volumio[1226]: info: Scanning category miscellanea Dec 29 16:01:05 garage volumio[1226]: info: Scanning category music_service Dec 29 16:01:05 garage volumio[1226]: info: Scanning category plugins.json Dec 29 16:01:05 garage volumio[1226]: info: Scanning category system_controller Dec 29 16:01:05 garage volumio[1226]: info: Scanning category user_interface Dec 29 16:01:05 garage volumio[1226]: info: Scanning into folder /data/plugins/ Dec 29 16:01:05 garage volumio[1226]: info: Scanning category music_service Dec 29 16:01:05 garage volumio[1226]: info: Scanning category system_controller Dec 29 16:01:05 garage volumio[1226]: info: Scanning category system_hardware Dec 29 16:01:05 garage volumio[1226]: info: Scanning category user_interface Dec 29 16:01:05 garage volumio[1226]: info: Plugin folders cleanup completed Dec 29 16:01:05 garage volumio[1226]: info: ------------------------------------------- Dec 29 16:01:05 garage volumio[1226]: info: ----- Core plugins startup ---- Dec 29 16:01:05 garage volumio[1226]: info: ------------------------------------------- Dec 29 16:01:05 garage volumio[1226]: info: Loading plugins from folder /volumio/app/plugins/ Dec 29 16:01:05 garage volumio[1226]: info: Adding plugin upnp to MyMusic Plugins Dec 29 16:01:05 garage volumio[1226]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 29 16:01:05 garage volumio[1226]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 29 16:01:05 garage volumio[1226]: info: Loading plugins from folder /data/plugins/ Dec 29 16:01:05 garage volumio[1226]: info: Loading plugin "system"... Dec 29 16:01:05 garage volumio[1226]: info: Loading plugin "appearance"... Dec 29 16:01:06 garage systemd[1]: systemd-fsckd.service: Deactivated successfully. Dec 29 16:01:07 garage dhcpcd[611]: timed out Dec 29 16:01:07 garage sh[606]: timed out Dec 29 16:01:07 garage sh[540]: ifup: failed to bring up eth0 Dec 29 16:01:07 garage systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:01:07 garage systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Dec 29 16:01:07 garage volumio[1226]: info: Loading plugin "network"... Dec 29 16:01:07 garage volumio[1226]: info: Refreshing Cached IP Addresses Dec 29 16:01:07 garage sudo[1307]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:01:07 garage sudo[1307]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:07 garage sudo[1307]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:07 garage sudo[1308]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:01:07 garage sudo[1308]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:07 garage volumio[1226]: info: Loading plugin "services"... Dec 29 16:01:07 garage volumio[1226]: info: Loading plugin "alsa_controller"... Dec 29 16:01:07 garage sudo[1308]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:07 garage sudo[1317]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 29 16:01:07 garage sudo[1317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:07 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:01:07 garage volumio[1226]: info: Loading plugin "wizard"... Dec 29 16:01:07 garage volumio[1226]: info: Loading plugin "networkfs"... Dec 29 16:01:07 garage volumio[1226]: info: Starting Udev Watcher for removable devices Dec 29 16:01:08 garage sudo[1342]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=carmel,password=alinco,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.88.148/Public/music /mnt/NAS/NAS Dec 29 16:01:08 garage sudo[1342]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:08 garage volumio[1226]: info: Ignoring mount for partition: boot Dec 29 16:01:08 garage volumio[1226]: info: Ignoring mount for partition: volumio Dec 29 16:01:08 garage volumio[1226]: info: Ignoring mount for partition: volumio_data Dec 29 16:01:08 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:01:08 garage volumio[1226]: info: Loading plugin "volumio_command_line_client"... Dec 29 16:01:08 garage volumio[1226]: info: Loading plugin "upnp"... Dec 29 16:01:08 garage volumio[1226]: info: [1767020468130] Starting Upmpd Daemon Dec 29 16:01:08 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:01:08 garage volumio[1226]: info: Loading plugin "my_music"... Dec 29 16:01:08 garage kernel: netfs: FS-Cache loaded Dec 29 16:01:08 garage volumio[1226]: info: Loading plugin "mpd"... Dec 29 16:01:08 garage kernel: Key type cifs.spnego registered Dec 29 16:01:08 garage kernel: Key type cifs.idmap registered Dec 29 16:01:08 garage kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Dec 29 16:01:08 garage kernel: CIFS: Attempting to mount //192.168.88.148/Public/music Dec 29 16:01:09 garage sudo[1342]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:09 garage volumio[1226]: info: Loading plugin "upnp_browser"... Dec 29 16:01:09 garage systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Dec 29 16:01:09 garage systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 29 16:01:09 garage systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 29 16:01:09 garage upmpdcli[1379]: Could not open config: /tmp/upmpdcli.conf Dec 29 16:01:09 garage systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:01:09 garage systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Dec 29 16:01:10 garage systemd[1]: systemd-hostnamed.service: Deactivated successfully. Dec 29 16:01:11 garage volumio-remote-updater[653]: [2025-12-29 16:01:11] [connect] Successful connection Dec 29 16:01:11 garage sudo[1317]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:11 garage volumio[1226]: info: Starting UPNP Browser Dec 29 16:01:11 garage volumio[1226]: info: Loading plugin "alarm-clock"... Dec 29 16:01:12 garage volumio[1226]: info: Loading plugin "airplay_emulation"... Dec 29 16:01:12 garage volumio[1226]: info: Starting Shairport Sync Dec 29 16:01:12 garage volumio[1226]: info: Loading plugin "last_100"... Dec 29 16:01:12 garage volumio[1226]: info: Loading plugin "webradio"... Dec 29 16:01:12 garage volumio[1226]: info: Loading plugin "i2s_dacs"... Dec 29 16:01:12 garage volumio[1226]: info: Loading plugin "volumiodiscovery"... Dec 29 16:01:12 garage volumio[1226]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:01:12 garage node[1226]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:01:12 garage volumio[1226]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:01:12 garage volumio[1226]: *** WARNING *** For more information see Dec 29 16:01:12 garage volumio[1226]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:01:12 garage volumio[1226]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:01:12 garage volumio[1226]: *** WARNING *** For more information see Dec 29 16:01:12 garage volumio[1226]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 29 16:01:12 garage node[1226]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:01:12 garage node[1226]: *** WARNING *** For more information see Dec 29 16:01:12 garage node[1226]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:01:12 garage node[1226]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:01:12 garage node[1226]: *** WARNING *** For more information see Dec 29 16:01:12 garage volumio[1226]: info: Discovery: Started advertising with name: Garage Dec 29 16:01:12 garage nmbd[1035]: [2025/12/29 16:01:12.875110, 0] ../../source3/nmbd/nmbd_namequery.c:109(query_name_response) Dec 29 16:01:12 garage nmbd[1035]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.88.184 for name WORKGROUP<1d>. Dec 29 16:01:12 garage nmbd[1035]: This response was from IP 192.168.88.30, reporting an IP address of 192.168.88.30. Dec 29 16:01:12 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:01:12 garage volumio[1226]: info: Loading plugin "spop"... Dec 29 16:01:16 garage volumio[1226]: info: Loading plugin "now_playing"... Dec 29 16:01:19 garage volumio[1226]: info: Loading plugin "outputs"... Dec 29 16:01:19 garage volumio[1226]: info: Loading plugin "albumart"... Dec 29 16:01:19 garage volumio[1226]: info: Plugin example_plugin is not enabled Dec 29 16:01:19 garage volumio[1226]: info: Loading plugin "inputs"... Dec 29 16:01:19 garage volumio[1226]: info: Loading plugin "updater_comm"... Dec 29 16:01:19 garage volumio[1226]: info: Plugin mpdemulation is not enabled Dec 29 16:01:19 garage volumio[1226]: info: Loading plugin "rest_api"... Dec 29 16:01:19 garage volumio[1226]: info: Loading plugin "websocket"... Dec 29 16:01:19 garage volumio[1226]: info: Starting Socket.io Server version 1.7.4 Dec 29 16:01:19 garage volumio[1226]: info: Loading plugin "backup_restore"... Dec 29 16:01:20 garage volumio[1226]: info: Applying required configuration parameters for plugin backup_restore Dec 29 16:01:20 garage volumio[1226]: info: Loading plugin "gpio_control"... Dec 29 16:01:20 garage volumio[1400]: Forking 3 albumart workers Dec 29 16:01:21 garage volumio[1226]: gpiox_arm32 V2.2.1 Dec 29 16:01:22 garage systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 29 16:01:24 garage systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Dec 29 16:01:24 garage systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 29 16:01:24 garage systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 29 16:01:24 garage upmpdcli[1456]: Could not open config: /tmp/upmpdcli.conf Dec 29 16:01:24 garage systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:01:24 garage systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Dec 29 16:01:25 garage volumio[1226]: info: Applying required configuration parameters for plugin gpio_control Dec 29 16:01:25 garage volumio[1226]: info: Loading plugin "ir_controller"... Dec 29 16:01:26 garage volumio-remote-updater[653]: [2025-12-29 16:01:26] [connect] Successful connection Dec 29 16:01:26 garage volumio[1226]: info: Applying required configuration parameters for plugin ir_controller Dec 29 16:01:27 garage volumio[1410]: Starting albumart workers Dec 29 16:01:28 garage volumio[1226]: info: Loading plugin "rotaryencoder2"... Dec 29 16:01:28 garage volumio[1411]: Starting albumart workers Dec 29 16:01:29 garage systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 29 16:01:29 garage systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 29 16:01:30 garage volumio[1412]: Starting albumart workers Dec 29 16:01:32 garage volumio[1226]: info: Loading plugin "Systeminfo"... Dec 29 16:01:34 garage volumio[1226]: info: Loading plugin "peppymeterbasic"... Dec 29 16:01:37 garage volumio[1226]: info: Loading plugin "touch_display"... Dec 29 16:01:38 garage volumio[1226]: info: Applying required configuration parameters for plugin touch_display Dec 29 16:01:39 garage volumio[1226]: info: Loading i18n strings for locale en Dec 29 16:01:39 garage volumio[1226]: Updating browse sources language Dec 29 16:01:39 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:01:40 garage systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4. Dec 29 16:01:40 garage systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 29 16:01:40 garage systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 29 16:01:40 garage upmpdcli[1512]: Could not open config: /tmp/upmpdcli.conf Dec 29 16:01:40 garage systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:01:40 garage systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::initPlayerControls Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:01:40 garage volumio[1226]: Express server listening on port 3000 Dec 29 16:01:40 garage volumio[1226]: [Metrics] WebUI: 38s 51.08ms Dec 29 16:01:40 garage volumio[1226]: info: CoreStateMachine::resetVolumioState Dec 29 16:01:40 garage volumio[1226]: info: CoreStateMachine::getcurrentVolume Dec 29 16:01:40 garage volumio[1226]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:01:40 garage sudo[1519]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:01:40 garage sudo[1519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:40 garage sudo[1520]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:01:40 garage sudo[1520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:40 garage sudo[1519]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:40 garage sudo[1520]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:41 garage volumio[1226]: info: Volumio Network Manager: Network status updated: 2 Dec 29 16:01:41 garage volumio-remote-updater[653]: [2025-12-29 16:01:41] [connect] Successful connection Dec 29 16:01:41 garage volumio[1226]: info: VolumeController:: Volume=31 Mute =false Dec 29 16:01:41 garage volumio[1226]: info: CoreStateMachine::pushState Dec 29 16:01:41 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:41 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:01:41 garage volumio[1226]: info: CoreCommandRouter::volumioPushState Dec 29 16:01:41 garage volumio[1226]: info: CoreStateMachine::updateTrackBlock Dec 29 16:01:41 garage volumio[1226]: info: CorePlayQueue::getTrackBlock Dec 29 16:01:41 garage volumio[1226]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:01:41 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:01:41 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:42 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:01:42 garage volumio[1226]: info: Reloading queue from file Dec 29 16:01:42 garage volumio[1226]: info: Setting Device type: Raspberry PI Dec 29 16:01:42 garage volumio[1226]: info: CoreStateMachine::setRepeat null single undefined Dec 29 16:01:42 garage volumio[1226]: info: CoreStateMachine::pushState Dec 29 16:01:42 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:42 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:01:42 garage volumio[1226]: info: CoreCommandRouter::volumioPushState Dec 29 16:01:42 garage volumio[1226]: info: CoreStateMachine::setRandom null Dec 29 16:01:42 garage volumio[1226]: info: CoreStateMachine::pushState Dec 29 16:01:42 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:42 garage volumio[1226]: info: CoreCommandRouter::volumioPushState Dec 29 16:01:42 garage volumio[1226]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Dec 29 16:01:42 garage volumio[1226]: info: Completed loading Core Plugins Dec 29 16:01:42 garage volumio[1226]: info: Preparing to generate the ALSA configuration file Dec 29 16:01:42 garage volumio[1226]: info: Listing playlists Dec 29 16:01:42 garage volumio[1226]: info: Listing playlists Dec 29 16:01:42 garage volumio[1226]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 29 16:01:42 garage volumio[1226]: info: Reading ALSA contributions from plugins. Dec 29 16:01:42 garage volumio[1226]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 29 16:01:43 garage volumio-remote-updater[653]: [2025-12-29 16:01:42] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767020501 101 Dec 29 16:01:43 garage sudo[1536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 29 16:01:43 garage volumio[1226]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Dec 29 16:01:43 garage sudo[1536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:43 garage volumio[1226]: info: VolumeController:: Volume=31 Mute =false Dec 29 16:01:43 garage volumio[1226]: info: CoreStateMachine::pushState Dec 29 16:01:43 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:43 garage volumio[1226]: info: CoreCommandRouter::volumioPushState Dec 29 16:01:43 garage volumio[1226]: info: Discovery: adding 8c7e1a76-7eff-4a97-8a00-0e4b4cf16710 Dec 29 16:01:43 garage volumio[1226]: info: Discovery: Found device Garage Dec 29 16:01:43 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:01:43 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:43 garage volumio[1226]: info: Discovery: this is already registered, 8c7e1a76-7eff-4a97-8a00-0e4b4cf16710 Dec 29 16:01:43 garage volumio[1226]: info: Discovery: Found device Garage Dec 29 16:01:43 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:01:43 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:43 garage volumio[1226]: info: Asound.conf file unchanged, so no further update is needed Dec 29 16:01:43 garage volumio[1226]: info: Output device has changed, restarting MPD Dec 29 16:01:43 garage volumio[1226]: info: Output device has changed, restarting Shairport Sync Dec 29 16:01:43 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:43 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:01:44 garage sudo[1540]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:01:44 garage sudo[1540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:44 garage sudo[1540]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:44 garage sudo[1542]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:01:44 garage sudo[1542]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:44 garage volumio[1226]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:01:44 garage volumio[1226]: info: ___________ START PLUGINS ___________ Dec 29 16:01:44 garage volumio[1226]: info: ControllerMpd::onStart: Initializing MPD Dec 29 16:01:44 garage volumio[1226]: info: Creating MPD Configuration file Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:01:44 garage volumio[1226]: info: [1767020504258] CoreMusicLibrary::Adding element Media Servers Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:01:44 garage systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:01:44 garage systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:01:44 garage sudo[1550]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:01:44 garage sudo[1550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:44 garage sudo[1550]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:44 garage volumio[1226]: info: UPNP Browser: Client initialized successfully Dec 29 16:01:44 garage sudo[1553]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:01:44 garage sudo[1553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:44 garage sudo[1554]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 29 16:01:44 garage sudo[1554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 29 16:01:44 garage sudo[1557]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 29 16:01:44 garage sudo[1554]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:01:44 garage systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:01:44 garage systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:01:44 garage systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:01:44 garage systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:01:44 garage systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:01:44 garage systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:01:44 garage systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:01:44 garage volumio[1226]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:01:44 garage volumio[1226]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:01:44 garage volumio[1226]: info: [1767020504760] CoreMusicLibrary::Adding element Last_100 Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:01:44 garage volumio[1226]: info: [1767020504801] CoreMusicLibrary::Adding element Webradio Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:01:44 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:01:44 garage sudo[1564]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 29 16:01:44 garage sudo[1564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 29 16:01:44 garage sudo[1569]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 29 16:01:44 garage sudo[1564]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:44 garage volumio[1226]: info: Initializing BBC Radios Dec 29 16:01:45 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:01:45 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:01:45 garage volumio[1226]: info: Creating Spotify config file Dec 29 16:01:45 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:47 garage volumio[1226]: info: [now-playing] ConfigUpdater: config is up to date. Dec 29 16:01:47 garage volumio[1226]: info: Loading i18n strings for locale en Dec 29 16:01:47 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:01:48 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 29 16:01:48 garage sudo[1585]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Dec 29 16:01:48 garage sudo[1585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:48 garage volumio[1226]: info: Loading i18n strings for locale en Dec 29 16:01:48 garage sudo[1585]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:48 garage sudo[1588]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd_aloop index=7 pcm_substreams=2 Dec 29 16:01:48 garage sudo[1588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:48 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:01:48 garage volumio[1226]: info: Volumio Calling Home Dec 29 16:01:48 garage sudo[1588]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:48 garage sudo[1606]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /data/volumiokioskextensions/IframeKeyboardBridge Dec 29 16:01:48 garage sudo[1606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:49 garage sudo[1606]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:49 garage volumio[1226]: info: Preparing to generate the ALSA configuration file Dec 29 16:01:50 garage sudo[1621]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R a+rwX /etc/lirc/irexec.lircrc /etc/lirc/lirc_options.conf /etc/lirc/lircd.conf /etc/lirc/lircd.conf.d /etc/lirc/lircmd.conf /etc/lirc/lircrc Dec 29 16:01:50 garage sudo[1621]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:50 garage sudo[1625]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Dec 29 16:01:50 garage sudo[1625]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:50 garage sudo[1623]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Dec 29 16:01:50 garage sudo[1623]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:50 garage sudo[1621]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:50 garage sudo[1629]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 29 16:01:50 garage sudo[1629]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:50 garage systemd[1]: Reloading. Dec 29 16:01:51 garage volumio[1226]: info: [now-playing] App is listening on port 4004. Dec 29 16:01:51 garage volumio[1226]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Dec 29 16:01:52 garage volumio[1226]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 29 16:01:52 garage volumio[1226]: info: Reading ALSA contributions from plugins. Dec 29 16:01:52 garage volumio[1226]: info: touch_display: Backlight interface detected. Dec 29 16:01:52 garage mpd[1570]: 2025-12-29T16:01:52 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 29 16:01:52 garage systemd[1]: Started mpd.service - Music Player Daemon. Dec 29 16:01:52 garage sudo[1542]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:52 garage sudo[1625]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:52 garage sudo[1623]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:52 garage systemd[1]: Reloading. Dec 29 16:01:52 garage sudo[1553]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:52 garage volumio[1226]: info: ir_controller: File permissions successfully set on /etc/lirc/*. Dec 29 16:01:52 garage volumio[1226]: info: snd_dummy loaded Dec 29 16:01:53 garage volumio[1226]: info: MPD Permissions set Dec 29 16:01:53 garage volumio[1226]: info: MPD Permissions set Dec 29 16:01:53 garage sudo[1674]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay rotary-encoder pin_a=23 pin_b=24 relative_axis=true steps-per-period=1 Dec 29 16:01:53 garage sudo[1674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:53 garage kernel: rotary-encoder rotary@17: gray Dec 29 16:01:53 garage kernel: input: rotary@17 as /devices/platform/rotary@17/input/input1 Dec 29 16:01:53 garage sudo[1655]: 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 29 16:01:53 garage sudo[1674]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:53 garage sudo[1655]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:53 garage sudo[1655]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:54 garage volumio[1226]: info: touch_display: systemctl stop getty@tty1.service succeeded. Dec 29 16:01:54 garage volumio[1226]: info: touch_display: systemctl disable getty@tty1.service succeeded. Dec 29 16:01:54 garage volumio[1226]: info: Volumio called home Dec 29 16:01:54 garage sudo[1629]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:54 garage volumio[1226]: info: Spotify config file written Dec 29 16:01:54 garage sudo[1697]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 16:01:54 garage sudo[1697]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:54 garage 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 29 16:01:54 garage 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 29 16:01:54 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:01:54 garage go-librespot[1701]: go-librespot daemon starting... Dec 29 16:01:54 garage sudo[1697]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:54 garage volumio[1226]: info: MPD running with PID1570 Dec 29 16:01:54 garage volumio[1226]: ,establishing connection Dec 29 16:01:54 garage volumio[1226]: info: touch_display: systemctl daemon-reload succeeded. Dec 29 16:01:54 garage volumio[1226]: info: touch_display: IframeKeyboardBridge extension installed successfully Dec 29 16:01:54 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:54 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:01:55 garage sudo[1709]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Dec 29 16:01:55 garage sudo[1709]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage go-librespot[1702]: time="2025-12-29T16:01:55+01:00" level=info msg="running go-librespot 0.4.0" Dec 29 16:01:55 garage go-librespot[1702]: time="2025-12-29T16:01:55+01:00" level=debug msg="app state loaded" Dec 29 16:01:55 garage go-librespot[1702]: time="2025-12-29T16:01:55+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:01:55 garage systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5. Dec 29 16:01:55 garage systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 29 16:01:55 garage systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 29 16:01:55 garage systemd[1]: Started volumio-kiosk.service - Volumio Kiosk. Dec 29 16:01:55 garage sudo[1536]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:55 garage sudo[1709]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:01:55 garage volumio[1226]: info: No need to fix Spotify hosts Dec 29 16:01:55 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:01:55 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:55 garage startx[1754]: X.Org X Server 1.21.1.7 Dec 29 16:01:55 garage startx[1754]: X Protocol Version 11, Revision 0 Dec 29 16:01:55 garage startx[1754]: Current Operating System: Linux garage 6.12.47-v7+ #1904 SMP Mon Sep 15 13:05:52 BST 2025 armv7l Dec 29 16:01:55 garage startx[1754]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 clk_ignore_unused 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=dafa3844-b779-48cd-9b4c-01ecfd09e0f4 imgfile=/volumio_current.sqsh bootpart=UUID=3B89-0B23 datapart=UUID=752d19ad-b702-471d-847a-f79ae83515d0 uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Dec 29 16:01:55 garage startx[1754]: xorg-server 2:21.1.7-3+rpt3+deb12u11 (https://www.debian.org/support) Dec 29 16:01:55 garage startx[1754]: Current version of pixman: 0.44.0 Dec 29 16:01:55 garage startx[1754]: Before reporting problems, check http://wiki.x.org Dec 29 16:01:55 garage startx[1754]: to make sure that you have the latest version. Dec 29 16:01:55 garage startx[1754]: Markers: (--) probed, (**) from config file, (==) default setting, Dec 29 16:01:55 garage startx[1754]: (++) from command line, (!!) notice, (II) informational, Dec 29 16:01:55 garage startx[1754]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Dec 29 16:01:55 garage startx[1754]: (==) Log file: "/var/log/Xorg.0.log", Time: Mon Dec 29 16:01:55 2025 Dec 29 16:01:55 garage startx[1754]: (==) Using config directory: "/etc/X11/xorg.conf.d" Dec 29 16:01:55 garage startx[1754]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Dec 29 16:01:55 garage go-librespot[1702]: time="2025-12-29T16:01:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:01:55 garage go-librespot[1702]: time="2025-12-29T16:01:55+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:01:55 garage go-librespot[1702]: time="2025-12-29T16:01:55+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:01:55 garage go-librespot[1702]: time="2025-12-29T16:01:55+01:00" level=info msg="zeroconf server listening on port 41899" Dec 29 16:01:55 garage go-librespot[1702]: time="2025-12-29T16:01:55+01:00" level=debug msg="obtained new client token: AACQcoyILDIjYEaQUF8u3QKhzsJoPPUUbdYQzwG/l4OuHcCuLos7P6nX6PcmH+CQspiKATiMA5CtqvidwpYIU3+HeFCygSqZ4KJ37h83N0/OozP2TpPGvuDwcMfGPMmucejX/u4cD1ZcGYC0/7rVrVYWp6ThVcQgW/MUiTIUsPbD3W3H9CsPg3IVBQbwWaoyxA9XZ+Ba2ya+wHLQgUM6HKNstflgSX0hPYymvqJSu8sgcHKcCjgJKBUY" Dec 29 16:01:56 garage go-librespot[1702]: time="2025-12-29T16:01:56+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 16:01:56 garage go-librespot[1702]: time="2025-12-29T16:01:56+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: read tcp 192.168.88.184:37894->104.199.65.9:4070: read: connection reset by peer" Dec 29 16:01:56 garage systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:01:56 garage systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:01:56 garage volumio[1226]: error: MPD error: The expression evaluated to a falsy value: Dec 29 16:01:56 garage volumio[1226]: assert.ok(self.idling) Dec 29 16:01:56 garage volumio[1226]: error: The expression evaluated to a falsy value: Dec 29 16:01:56 garage volumio[1226]: assert.ok(self.idling) Dec 29 16:01:56 garage volumio[1226]: error: MPD error: The expression evaluated to a falsy value: Dec 29 16:01:56 garage volumio[1226]: assert.ok(self.idling) Dec 29 16:01:56 garage volumio[1226]: error: The expression evaluated to a falsy value: Dec 29 16:01:56 garage volumio[1226]: assert.ok(self.idling) Dec 29 16:01:57 garage sudo[1778]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-key gpio=27 active_low=true gpio_pull=up keycode=20 Dec 29 16:01:57 garage sudo[1778]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:57 garage sudo[1778]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:57 garage kernel: input: button@1b as /devices/platform/button@1b/input/input2 Dec 29 16:01:57 garage volumio[1226]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 29 16:01:57 garage volumio[1226]: info: Upmpdcli Daemon Started Dec 29 16:01:57 garage volumio[1226]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Dec 29 16:01:57 garage volumio[1226]: info: touch_display: Volumio Kiosk started. Dec 29 16:01:57 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:01:57 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:01:58 garage sudo[1807]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:01:58 garage sudo[1807]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:58 garage sudo[1802]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:01:58 garage sudo[1802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:58 garage sudo[1818]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/rpi_backlight/brightness Dec 29 16:01:58 garage sudo[1818]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:58 garage systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:01:58 garage sudo[1818]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:58 garage mpd_monitor.sh[1825]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:01:58 garage sudo[1807]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:58 garage systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:01:58 garage systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:01:58 garage systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:01:58 garage volumio[1226]: info: touch_display: Raspberry Pi Foundation touch screen detected. Dec 29 16:01:58 garage systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:01:58 garage sudo[1802]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:58 garage mpd_monitor.sh[1844]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:01:58 garage sudo[1843]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Dec 29 16:01:58 garage sudo[1843]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:58 garage sudo[1843]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:58 garage sudo[1858]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Dec 29 16:01:58 garage sudo[1858]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:58 garage sudo[1858]: pam_unix(sudo:session): session closed for user root Dec 29 16:01:58 garage volumio[1226]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 16:01:58 garage volumio[1226]: SPOTIFY: BQB5qhugm8n6oEVmKh-VysTcJ7rKLw5OnfiFUn1F3XHCPyC2ZsSPeN9UHZRGc7htu5y508FLuuFjkzHjp0-W1kes73n9iKrWt0reUBtP2yVilvTUijyVc3AqsxpX-sWJxVRNkLyaL1DSa4s_XyNQdx3FvVoDFVnz1mh5HaAm8q0TPY7m7-uyajSY8kr-2-eeTHMGdzqGBVjLoJWOLIQ6SPpfRII1D0WMsZe0RYO9W6v6gORclegKnu3E7jjJiKvYIKH7BsIpep1mQgf88TEX2L26qdZHa4y6GgE7SVibYYFKHmDyh2VD_oQ-6MIO Dec 29 16:01:58 garage volumio[1226]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 16:01:58 garage volumio[1226]: info: New Spotify access token = BQB5qhugm8n6oEVmKh-VysTcJ7rKLw5OnfiFUn1F3XHCPyC2ZsSPeN9UHZRGc7htu5y508FLuuFjkzHjp0-W1kes73n9iKrWt0reUBtP2yVilvTUijyVc3AqsxpX-sWJxVRNkLyaL1DSa4s_XyNQdx3FvVoDFVnz1mh5HaAm8q0TPY7m7-uyajSY8kr-2-eeTHMGdzqGBVjLoJWOLIQ6SPpfRII1D0WMsZe0RYO9W6v6gORclegKnu3E7jjJiKvYIKH7BsIpep1mQgf88TEX2L26qdZHa4y6GgE7SVibYYFKHmDyh2VD_oQ-6MIO Dec 29 16:01:58 garage volumio[1226]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 29 16:01:58 garage volumio[1226]: error: updateQueue error: null Dec 29 16:01:58 garage volumio[1226]: 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 29 16:01:59 garage volumio[1226]: info: touch_display: X display number found: 0 Dec 29 16:01:59 garage systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 29 16:01:59 garage systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:01:59 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:01:59 garage go-librespot[1877]: go-librespot daemon starting... Dec 29 16:01:59 garage go-librespot[1880]: time="2025-12-29T16:01:59+01:00" level=info msg="running go-librespot 0.4.0" Dec 29 16:01:59 garage go-librespot[1880]: time="2025-12-29T16:01:59+01:00" level=debug msg="app state loaded" Dec 29 16:01:59 garage go-librespot[1880]: time="2025-12-29T16:01:59+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:01:59 garage volumio[1226]: info: Starting Shairport Sync Dec 29 16:01:59 garage volumio[1226]: info: Starting Shairport Sync Dec 29 16:01:59 garage volumio[1226]: info: Starting Shairport Sync Dec 29 16:01:59 garage sudo[1890]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:01:59 garage sudo[1890]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:01:59 garage go-librespot[1880]: time="2025-12-29T16:01:59+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 29 16:01:59 garage go-librespot[1880]: time="2025-12-29T16:01:59+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 29 16:01:59 garage go-librespot[1880]: time="2025-12-29T16:01:59+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 29 16:01:59 garage go-librespot[1880]: time="2025-12-29T16:01:59+01:00" level=info msg="zeroconf server listening on port 44711" Dec 29 16:01:59 garage sudo[1892]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:01:59 garage sudo[1892]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:00 garage sudo[1896]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:02:00 garage sudo[1896]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:00 garage systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:02:00 garage systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:02:00 garage systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:02:00 garage systemd[1]: shairport-sync.service: Consumed 1.670s CPU time. Dec 29 16:02:00 garage go-librespot[1880]: time="2025-12-29T16:02:00+01:00" level=debug msg="obtained new client token: AACW77Dcck2Rf6UBrrq/a7C1fg4B4ZrzFEyXD6cUIjTAh0fOTY3u5KUFZqp1q7ZtwDx3NohnI/fQodeVtTr6lZ7gyqxDv4xaMV7si2ZqwF5AhAcsDQ8GmoS69YscuC5K2U93qtWYWkdBMSSmZYJV78NRWg0OnhQOBec9uF0qUEtNV81xnK6IsLKZAlOExX4Pvegl5hYQJeccBtI4wBCQvWKC5S2NeDKtcgVU4TjNDXI0yUxGnd0icg==" Dec 29 16:02:00 garage systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:02:00 garage sudo[1896]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:00 garage systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:02:00 garage systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:02:00 garage systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:02:00 garage systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:02:00 garage sudo[1890]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:00 garage systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:02:00 garage go-librespot[1880]: time="2025-12-29T16:02:00+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 16:02:00 garage systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:02:00 garage systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:02:00 garage systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:02:00 garage sudo[1892]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:00 garage go-librespot[1880]: time="2025-12-29T16:02:00+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: read tcp 192.168.88.184:37906->104.199.65.9:4070: read: connection reset by peer" Dec 29 16:02:00 garage systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:02:00 garage systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:02:00 garage volumio[1226]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Dec 29 16:02:00 garage volumio[1226]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Dec 29 16:02:00 garage volumio[1226]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Dec 29 16:02:00 garage volumio[1226]: info: touch_display: File permissions for backlight brightness control set. Dec 29 16:02:00 garage volumio[1226]: info: Successfully started MPD Monitor Dec 29 16:02:00 garage volumio[1226]: info: Successfully started MPD Monitor Dec 29 16:02:00 garage volumio[1226]: info: go-librespot daemon successfully initialized Dec 29 16:02:00 garage volumio[1226]: error: ir_controller: Error copying configurations: Error: ENOENT: no such file or directory, scandir '/data/plugins/system_hardware/ir_controller/configurations/TCL RC3000E02' Dec 29 16:02:00 garage volumio[1226]: info: ir_controller: HAT did not load /proc/device-tree/ir_receiver! Dec 29 16:02:01 garage volumio[1226]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Dec 29 16:02:01 garage sudo[1945]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay rotary-encoder pin_a=5 pin_b=6 relative_axis=true steps-per-period=1 Dec 29 16:02:01 garage sudo[1945]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:01 garage volumio[1226]: info: Shairport-Sync Started Dec 29 16:02:01 garage volumio[1226]: Error adding Membership: Error: addMembership EINVAL Dec 29 16:02:01 garage volumio[1226]: info: Shairport-Sync Started Dec 29 16:02:01 garage volumio[1226]: info: Shairport-Sync Started Dec 29 16:02:01 garage volumio[1226]: info: Asound.conf file unchanged, so no further update is needed Dec 29 16:02:01 garage volumio[1226]: info: Output device has changed, restarting MPD Dec 29 16:02:01 garage kernel: rotary-encoder rotary@5: gray Dec 29 16:02:01 garage volumio[1226]: info: Output device has changed, restarting Shairport Sync Dec 29 16:02:01 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:01 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:02:01 garage kernel: input: rotary@5 as /devices/platform/rotary@5/input/input3 Dec 29 16:02:01 garage sudo[1945]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:01 garage volumio[1226]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:02:01 garage sudo[1955]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:02:01 garage sudo[1955]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:01 garage sudo[1960]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:02:01 garage sudo[1960]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:01 garage sudo[1955]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:01 garage systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 29 16:02:01 garage volumio[1226]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 29 16:02:01 garage volumio[1226]: error: MPD error: Error: write EPIPE Dec 29 16:02:01 garage volumio[1226]: error: write EPIPE {"code":"EPIPE","errno":-32,"syscall":"write"} Dec 29 16:02:02 garage volumio[1226]: info: ir_controller: Raspberry Pi revision code: a020d3 Dec 29 16:02:02 garage volumio[1226]: info: touch_display: X display number found: 0 Dec 29 16:02:02 garage systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:02:02 garage systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:02:02 garage systemd[1]: mpd.service: Consumed 4.882s CPU time. Dec 29 16:02:02 garage systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:02:02 garage systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:02:02 garage systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:02:02 garage systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:02:02 garage systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:02:02 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:02:02 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:02:02 garage volumio[1226]: info: MPD Permissions set Dec 29 16:02:02 garage sudo[1982]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 29 16:02:02 garage sudo[1982]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 29 16:02:02 garage sudo[1982]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:02 garage volumio[1226]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 29 16:02:03 garage sudo[1988]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -r -1 Dec 29 16:02:03 garage sudo[1988]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:03 garage sudo[1988]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:03 garage sudo[2002]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Dec 29 16:02:03 garage sudo[2002]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:03 garage sudo[2002]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:03 garage systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 29 16:02:03 garage systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:02:03 garage volumio[1226]: info: touch_display: Setting screensaver timeout to 100 seconds. Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:03 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:02:03 garage go-librespot[2004]: go-librespot daemon starting... Dec 29 16:02:03 garage go-librespot[2006]: time="2025-12-29T16:02:03+01:00" level=info msg="running go-librespot 0.4.0" Dec 29 16:02:03 garage go-librespot[2006]: time="2025-12-29T16:02:03+01:00" level=debug msg="app state loaded" Dec 29 16:02:03 garage go-librespot[2006]: time="2025-12-29T16:02:03+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:02:03 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:02:04 garage volumio[1226]: info: Completed starting Core Plugins Dec 29 16:02:04 garage volumio[1226]: info: ------------------------------------------- Dec 29 16:02:04 garage volumio[1226]: info: ----- MyVolumio plugins startup ---- Dec 29 16:02:04 garage go-librespot[2006]: time="2025-12-29T16:02:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:02:04 garage go-librespot[2006]: time="2025-12-29T16:02:04+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:02:04 garage go-librespot[2006]: time="2025-12-29T16:02:04+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:02:04 garage sudo[2019]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Dec 29 16:02:04 garage sudo[2019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:04 garage volumio[1226]: info: ------------------------------------------- Dec 29 16:02:04 garage volumio[1226]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 29 16:02:04 garage sudo[2019]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:04 garage go-librespot[2006]: time="2025-12-29T16:02:04+01:00" level=info msg="zeroconf server listening on port 46883" Dec 29 16:02:04 garage go-librespot[2006]: time="2025-12-29T16:02:04+01:00" level=debug msg="obtained new client token: AACZfNpjTIImS4b1UNOj55IK1wba4xtWwpyM/7qkx9eZP1Ie4ge1SJo3y6TX9Ajo3TN54lOMduT8FLxgOfb3LF8hGZ0xvhcobgzACELRvVfhN+5L1HnJaIsBmaxLXouxqtBNrgQA1F4R58PVq+HVPFpc0Ou9iu57lVClaC6heE73WVdTmq7+lsbqF/6WzMnxzun/8KGhUM9jYy1DvMpEzhURqW4fhVP/dKqJcFLJZpYo/woildAEMQ==" Dec 29 16:02:04 garage volumio[1226]: info: Initializing connection to go-librespot Websocket Dec 29 16:02:04 garage go-librespot[2006]: time="2025-12-29T16:02:04+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 16:02:05 garage go-librespot[2006]: time="2025-12-29T16:02:05+01:00" level=debug msg="new websocket client" Dec 29 16:02:05 garage volumio[1226]: info: Starting Shairport Sync Dec 29 16:02:05 garage go-librespot[2006]: time="2025-12-29T16:02:05+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: read tcp 192.168.88.184:45388->104.199.65.9:4070: read: connection reset by peer" Dec 29 16:02:05 garage systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:02:05 garage systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:02:05 garage volumio[1226]: info: Connection to go-librespot Websocket established Dec 29 16:02:05 garage sudo[2035]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:02:05 garage sudo[2035]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:05 garage volumio[1226]: verbose: New Socket.io Connection to 192.168.88.184 from 192.168.88.76 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Dec 29 16:02:05 garage systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:02:05 garage systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:02:05 garage systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:02:05 garage systemd[1]: shairport-sync.service: Consumed 1.339s CPU time. Dec 29 16:02:05 garage sudo[2042]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-ir gpio_pin=25 gpio_pull=up Dec 29 16:02:05 garage systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:02:05 garage sudo[2042]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:05 garage sudo[2035]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:05 garage kernel: Registered IR keymap rc-rc6-mce Dec 29 16:02:05 garage sudo[2042]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:05 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:02:05 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:02:05 garage volumio[1226]: info: Connection to go-librespot Websocket closed Dec 29 16:02:05 garage kernel: IR RC6 protocol handler initialized Dec 29 16:02:05 garage volumio[1226]: info: ir_controller: Overlay gpio-ir gpio_pin=25 gpio_pull=up loaded. Dec 29 16:02:05 garage kernel: rc rc0: gpio_ir_recv as /devices/platform/ir-receiver@19/rc/rc0 Dec 29 16:02:05 garage kernel: rc rc0: lirc_dev: driver gpio_ir_recv registered at minor = 0, raw IR receiver, no transmitter Dec 29 16:02:05 garage kernel: input: gpio_ir_recv as /devices/platform/ir-receiver@19/rc/rc0/input4 Dec 29 16:02:06 garage volumio[1226]: info: Shairport-Sync Started Dec 29 16:02:06 garage systemd-logind[646]: Watching system buttons on /dev/input/event4 (gpio_ir_recv) Dec 29 16:02:06 garage volumio[1226]: SPOTIFY: User informations: {"country":"MT","display_name":"cfmt","email":"cfarr_mt@yahoo.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31wrmgdvir3k6mkgbw2lmiavhyty"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31wrmgdvir3k6mkgbw2lmiavhyty","id":"31wrmgdvir3k6mkgbw2lmiavhyty","images":[],"product":"premium","type":"user","uri":"spotify:user:31wrmgdvir3k6mkgbw2lmiavhyty"} Dec 29 16:02:06 garage volumio[1226]: info: Spotify Successfully logged in Dec 29 16:02:06 garage sudo[2076]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart lircd.service Dec 29 16:02:06 garage sudo[2076]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:06 garage volumio[1226]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:02:06 garage volumio[1226]: info: [1767020526422] CoreMusicLibrary::Adding element Spotify Dec 29 16:02:06 garage volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:02:06 garage volumio[1226]: Cannot find translation for source Spotify Dec 29 16:02:06 garage systemd[1]: Starting lircd-setup.service - lircd(8) initialization helper tool... Dec 29 16:02:06 garage mpd[1986]: 2025-12-29T16:02:06 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 29 16:02:06 garage systemd[1]: Started mpd.service - Music Player Daemon. Dec 29 16:02:07 garage sudo[1960]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:07 garage lircd-setup[2078]: /usr/sbin/lircd-setup:37: DeprecationWarning: The SafeConfigParser class has been renamed to ConfigParser in Python 3.2. This alias will be removed in Python 3.12. Use ConfigParser directly instead. Dec 29 16:02:07 garage lircd-setup[2078]: parser = configparser.SafeConfigParser() Dec 29 16:02:07 garage systemd[1]: lircd-setup.service: Deactivated successfully. Dec 29 16:02:07 garage systemd[1]: Finished lircd-setup.service - lircd(8) initialization helper tool. Dec 29 16:02:07 garage systemd[1]: Starting lircd.service - Flexible IR remote input/output application support... Dec 29 16:02:07 garage lircd-0.10.1[2087]: Info: lircd: Opening log, level: Info Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Version: lircd 0.10.1 Dec 29 16:02:07 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:02:07 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: System info: Linux garage 6.12.47-v7+ #1904 SMP Mon Sep 15 13:05:52 BST 2025 armv7l GNU/Linux Dec 29 16:02:07 garage volumio[1226]: error: updateQueue error: null Dec 29 16:02:07 garage lircd-0.10.1[2087]: Info: Initial device: /dev/lirc0 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: 'lirc' written to protocols file /sys/class/rc/rc0/protocols Dec 29 16:02:07 garage lircd-0.10.1[2087]: Info: Initial device: /dev/lirc0 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Info: [lirc] protocol is enabled Dec 29 16:02:07 garage lircd[2087]: lircd-0.10.1[2087]: Info: lircd: Opening log, level: Info Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: driver: default Dec 29 16:02:07 garage lircd[2087]: lircd-0.10.1[2087]: Notice: Using systemd fd Dec 29 16:02:07 garage lircd[2087]: lircd-0.10.1[2087]: Warning: Running as root Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: output: /var/run/lirc/lircd Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: nodaemon: 1 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: plugindir: /usr/lib/arm-linux-gnueabihf/lirc/plugins Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: logfile: syslog Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: immediate-init: 0 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: permission: 666 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: driver-options: Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: pidfile: /var/run/lirc/lircd.pid Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: listen: 0 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: connect: (null) Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: userelease: 0 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: effective_user: (null) Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: release_suffix: _EVUP Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: allow_simulate: 0 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: repeat_max: 600 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: configfile: /etc/lirc/lircd.conf Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Options: dynamic_codes: (null) Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Current driver: default Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Driver API version: 3 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Driver version: 0.10.0 Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Driver info: See file:///usr/share/doc/lirc/plugindocs/default.html Dec 29 16:02:07 garage lircd-0.10.1[2087]: Info: lircd: Opening log, level: Info Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: Using systemd fd Dec 29 16:02:07 garage lircd-0.10.1[2087]: Warning: Running as root Dec 29 16:02:07 garage lircd[2087]: lircd-0.10.1[2087]: Info: Using remote: lircd.conf. Dec 29 16:02:07 garage lircd-0.10.1[2087]: Info: Using remote: lircd.conf. Dec 29 16:02:07 garage lircd-0.10.1[2087]: Notice: lircd(default) ready, using /var/run/lirc/lircd Dec 29 16:02:07 garage systemd[1]: Started lircd.service - Flexible IR remote input/output application support. Dec 29 16:02:07 garage lircd[2087]: lircd-0.10.1[2087]: Notice: lircd(default) ready, using /var/run/lirc/lircd Dec 29 16:02:07 garage sudo[2076]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:08 garage volumio[1226]: info: CoreCommandRouter::volumioGetState Dec 29 16:02:08 garage volumio[1226]: info: CorePlayQueue::getTrack 0 Dec 29 16:02:08 garage volumio[1226]: info: Listing playlists Dec 29 16:02:08 garage volumio[1226]: info: Listing playlists Dec 29 16:02:08 garage volumio[1226]: info: ir_controller: systemctl restart lircd.service succeeded. Dec 29 16:02:08 garage sudo[2114]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart irexec.service Dec 29 16:02:08 garage sudo[2114]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:02:08 garage systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 29 16:02:08 garage systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:02:08 garage volumio[1226]: info: Getting Spotify volume Dec 29 16:02:08 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:02:08 garage go-librespot[2117]: go-librespot daemon starting... Dec 29 16:02:08 garage systemd[1]: Started irexec.service - Handle events from IR remotes decoded by lircd(8). Dec 29 16:02:08 garage sudo[2114]: pam_unix(sudo:session): session closed for user root Dec 29 16:02:08 garage go-librespot[2127]: time="2025-12-29T16:02:08+01:00" level=info msg="running go-librespot 0.4.0" Dec 29 16:02:08 garage go-librespot[2127]: time="2025-12-29T16:02:08+01:00" level=debug msg="app state loaded" Dec 29 16:02:08 garage go-librespot[2127]: time="2025-12-29T16:02:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:02:08 garage lircd[2087]: lircd-0.10.1[2087]: Notice: accepted new client on /var/run/lirc/lircd Dec 29 16:02:08 garage lircd[2087]: lircd-0.10.1[2087]: Info: [lirc] protocol is enabled Dec 29 16:02:08 garage lircd-0.10.1[2087]: Notice: accepted new client on /var/run/lirc/lircd Dec 29 16:02:08 garage lircd-0.10.1[2087]: Info: [lirc] protocol is enabled Dec 29 16:02:08 garage volumio[1226]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:02:09 garage volumio[1226]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 29 16:02:09 garage volumio[1226]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 29 16:02:09 garage volumio[1226]: errno: -111, Dec 29 16:02:09 garage volumio[1226]: code: 'ECONNREFUSED', Dec 29 16:02:09 garage volumio[1226]: syscall: 'connect', Dec 29 16:02:09 garage volumio[1226]: address: '127.0.0.1', Dec 29 16:02:09 garage volumio[1226]: port: 9879, Dec 29 16:02:09 garage volumio[1226]: response: undefined Dec 29 16:02:09 garage volumio[1226]: } Dec 29 16:02:09 garage volumio[1226]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:02:09 garage go-librespot[2127]: time="2025-12-29T16:02:09+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:02:09 garage go-librespot[2127]: time="2025-12-29T16:02:09+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:02:09 garage go-librespot[2127]: time="2025-12-29T16:02:09+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:02:09 garage go-librespot[2127]: time="2025-12-29T16:02:09+01:00" level=info msg="zeroconf server listening on port 35973" Dec 29 16:02:09 garage go-librespot[2127]: time="2025-12-29T16:02:09+01:00" level=debug msg="obtained new client token: AAAbbfd7R0dx3QyhwBJt3md1eEAz9R0Wz+YSOekYd0QWNDm6TDjsi8Pl8BEYF3E6iMGIeqJxdQacjJJdFJ/bIWjrChRqkHpJWUiR6NyIX4LpX0FfJbT+Mjc4iB8cFCwvKSKYHyN661RxSuYs4pkXvh+1rFo5eiGbSXJQuQHXCnGc6gLCqAKX8GuWMsmM6dHfSjErFS5WdjSmWP49T1h3Ercp8qrcPZrPD84Ha9mYwX71ZKak/7i9K05g" Dec 29 16:02:09 garage go-librespot[2127]: time="2025-12-29T16:02:09+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 16:02:09 garage go-librespot[2127]: time="2025-12-29T16:02:09+01:00" level=debug msg="completed keyexchange" Dec 29 16:02:09 garage go-librespot[2127]: time="2025-12-29T16:02:09+01:00" level=debug msg="completed challenge" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=info msg="authenticated AP" username="31************************ty" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=info msg="authenticated Login5" username="31************************ty" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="initializing zeroconf session" username="31************************ty" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="dealer connection opened" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=trace msg="starting accesspoint recv loop" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=trace msg="starting dealer recv loop" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=trace msg="received accesspoint ping" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="received connection id: NTFlZGM5MjctMzAz...MTRGQzRDMTRBQg==" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=trace msg="received accesspoint pong ack" Dec 29 16:02:10 garage go-librespot[2127]: time="2025-12-29T16:02:10+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 29 16:02:18 garage sudo[2178]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-29 16:01' Dec 29 16:02:18 garage sudo[2178]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"