Dec 16 18:27:50 volumio-manu systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 16 18:27:50 volumio-manu systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 16 18:27:50 volumio-manu systemd[1]: setdatetime-helper.service: Consumed 1.577s CPU time. Dec 16 18:27:50 volumio-manu systemd[1]: Reached target multi-user.target - Multi-User System. Dec 16 18:27:50 volumio-manu systemd[1]: Reached target graphical.target - Graphical Interface. Dec 16 18:27:50 volumio-manu systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Dec 16 18:27:50 volumio-manu systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Dec 16 18:27:50 volumio-manu systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Dec 16 18:27:50 volumio-manu systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Dec 16 18:27:50 volumio-manu systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Dec 16 18:27:50 volumio-manu systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Dec 16 18:27:50 volumio-manu systemd[1]: dpkg-db-backup.service: Deactivated successfully. Dec 16 18:27:50 volumio-manu systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Dec 16 18:27:50 volumio-manu systemd[1]: Startup finished in 15.242s (kernel) + 15.446s (userspace) = 30.689s. Dec 16 18:27:50 volumio-manu ntpd[849]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Dec 16 18:27:50 volumio-manu ntpd[849]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Dec 16 18:27:50 volumio-manu ntpd[849]: DNS: Pool taking: 193.52.136.2 Dec 16 18:27:50 volumio-manu ntpd[849]: DNS: Pool taking: 164.132.166.29 Dec 16 18:27:50 volumio-manu ntpd[849]: DNS: Pool taking: 51.68.44.27 Dec 16 18:27:50 volumio-manu ntpd[849]: DNS: Pool taking: 54.36.61.42 Dec 16 18:27:50 volumio-manu ntpd[849]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Dec 16 18:27:52 volumio-manu volumio-remote-updater[672]: [2025-12-16 18:27:52] [info] asio async_connect error: asio.system:111 (Connection refused) Dec 16 18:27:52 volumio-manu volumio-remote-updater[672]: [2025-12-16 18:27:52] [info] Error getting remote endpoint: asio.system:107 (Transport endpoint is not connected) Dec 16 18:27:52 volumio-manu volumio-remote-updater[672]: [2025-12-16 18:27:52] [error] handle_connect error: Connection refused Dec 16 18:27:54 volumio-manu volumio[1199]: info: ------------------------------------------- Dec 16 18:27:54 volumio-manu volumio[1199]: info: ----- Volumio3 ---- Dec 16 18:27:54 volumio-manu volumio[1199]: info: ------------------------------------------- Dec 16 18:27:54 volumio-manu volumio[1199]: info: ----- System startup ---- Dec 16 18:27:54 volumio-manu volumio[1199]: info: ------------------------------------------- Dec 16 18:27:55 volumio-manu volumio[1199]: info: MYVOLUMIO Environment detected Dec 16 18:27:55 volumio-manu volumio[1199]: info: Plugin folders cleanup Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning into folder /volumio/app/plugins/ Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category audio_interface Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category miscellanea Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category music_service Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category plugins.json Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category system_controller Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category user_interface Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning into folder /data/plugins/ Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category music_service Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category system_controller Dec 16 18:27:55 volumio-manu volumio[1199]: info: Scanning category system_hardware Dec 16 18:27:55 volumio-manu volumio[1199]: info: Plugin folders cleanup completed Dec 16 18:27:55 volumio-manu volumio[1199]: info: ------------------------------------------- Dec 16 18:27:55 volumio-manu volumio[1199]: info: ----- Core plugins startup ---- Dec 16 18:27:55 volumio-manu volumio[1199]: info: ------------------------------------------- Dec 16 18:27:55 volumio-manu volumio[1199]: info: Loading plugins from folder /volumio/app/plugins/ Dec 16 18:27:55 volumio-manu volumio[1199]: info: Adding plugin upnp to MyMusic Plugins Dec 16 18:27:55 volumio-manu volumio[1199]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 16 18:27:55 volumio-manu volumio[1199]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 16 18:27:55 volumio-manu volumio[1199]: info: Loading plugins from folder /data/plugins/ Dec 16 18:27:55 volumio-manu volumio[1199]: info: Loading plugin "system"... Dec 16 18:27:55 volumio-manu volumio[1199]: info: Loading plugin "appearance"... Dec 16 18:27:55 volumio-manu systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 1. Dec 16 18:27:55 volumio-manu systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 16 18:27:56 volumio-manu systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 16 18:27:56 volumio-manu upmpdcli[1252]: Could not open config: /tmp/upmpdcli.conf Dec 16 18:27:56 volumio-manu systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Dec 16 18:27:56 volumio-manu systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Dec 16 18:27:56 volumio-manu ntpd[849]: CLOCK: time stepped by 0.417916 Dec 16 18:27:56 volumio-manu ntpd[849]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Dec 16 18:27:58 volumio-manu volumio[1199]: info: Loading plugin "network"... Dec 16 18:27:58 volumio-manu volumio[1199]: info: Refreshing Cached IP Addresses Dec 16 18:27:58 volumio-manu sudo[1255]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 16 18:27:58 volumio-manu sudo[1255]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:27:58 volumio-manu sudo[1255]: pam_unix(sudo:session): session closed for user root Dec 16 18:27:58 volumio-manu volumio[1199]: info: Loading plugin "services"... Dec 16 18:27:58 volumio-manu sudo[1256]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 16 18:27:58 volumio-manu volumio[1199]: info: Loading plugin "alsa_controller"... Dec 16 18:27:58 volumio-manu sudo[1256]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:27:58 volumio-manu sudo[1256]: pam_unix(sudo:session): session closed for user root Dec 16 18:27:58 volumio-manu sudo[1263]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 16 18:27:58 volumio-manu sudo[1263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:27:58 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 16 18:27:58 volumio-manu volumio[1199]: info: Loading plugin "wizard"... Dec 16 18:27:58 volumio-manu volumio[1199]: info: Loading plugin "networkfs"... Dec 16 18:27:58 volumio-manu volumio[1199]: info: Starting Udev Watcher for removable devices Dec 16 18:27:58 volumio-manu sudo[1288]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Administrateur,password=Motdepasse,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //iMac-de-Emmanuel.local/AUDIO /mnt/NAS/AUDIO Dec 16 18:27:58 volumio-manu sudo[1288]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:27:58 volumio-manu volumio[1199]: info: Ignoring mount for partition: boot Dec 16 18:27:58 volumio-manu volumio[1199]: info: Ignoring mount for partition: volumio Dec 16 18:27:58 volumio-manu volumio[1199]: info: Ignoring mount for partition: volumio_data Dec 16 18:27:58 volumio-manu volumio[1199]: info: Mounting Device EFI Dec 16 18:27:58 volumio-manu sudo[1298]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/EFI -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Dec 16 18:27:58 volumio-manu sudo[1298]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:27:58 volumio-manu kernel: FAT-fs (sda1): utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! Dec 16 18:27:58 volumio-manu sudo[1298]: pam_unix(sudo:session): session closed for user root Dec 16 18:27:58 volumio-manu kernel: FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Dec 16 18:27:58 volumio-manu volumio[1199]: info: Mounting Device UNTITLED Dec 16 18:27:58 volumio-manu sudo[1308]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda2 /mnt/USB/UNTITLED -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Dec 16 18:27:58 volumio-manu sudo[1308]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:27:58 volumio-manu kernel: netfs: FS-Cache loaded Dec 16 18:27:59 volumio-manu kernel: FAT-fs (sda2): utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! Dec 16 18:27:59 volumio-manu sudo[1308]: pam_unix(sudo:session): session closed for user root Dec 16 18:27:59 volumio-manu kernel: FAT-fs (sda2): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Dec 16 18:27:59 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 16 18:27:59 volumio-manu volumio[1199]: info: Loading plugin "volumio_command_line_client"... Dec 16 18:27:59 volumio-manu kernel: Key type cifs.spnego registered Dec 16 18:27:59 volumio-manu kernel: Key type cifs.idmap registered Dec 16 18:27:59 volumio-manu 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 16 18:27:59 volumio-manu kernel: CIFS: Attempting to mount //iMac-de-Emmanuel.local/AUDIO Dec 16 18:27:59 volumio-manu volumio[1199]: info: Loading plugin "upnp"... Dec 16 18:27:59 volumio-manu volumio[1199]: info: [1765906079182] Starting Upmpd Daemon Dec 16 18:27:59 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 16 18:27:59 volumio-manu volumio[1199]: info: Loading plugin "my_music"... Dec 16 18:27:59 volumio-manu volumio[1199]: info: Loading plugin "mpd"... Dec 16 18:27:59 volumio-manu sudo[1288]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:00 volumio-manu volumio[1199]: info: Loading plugin "upnp_browser"... Dec 16 18:28:00 volumio-manu sudo[1263]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:02 volumio-manu volumio[1199]: info: Starting UPNP Browser Dec 16 18:28:02 volumio-manu volumio[1199]: info: Loading plugin "alarm-clock"... Dec 16 18:28:02 volumio-manu volumio[1199]: info: Loading plugin "airplay_emulation"... Dec 16 18:28:02 volumio-manu volumio[1199]: info: Starting Shairport Sync Dec 16 18:28:02 volumio-manu volumio[1199]: info: Loading plugin "last_100"... Dec 16 18:28:02 volumio-manu volumio[1199]: info: Loading plugin "webradio"... Dec 16 18:28:02 volumio-manu volumio[1199]: info: Loading plugin "i2s_dacs"... Dec 16 18:28:02 volumio-manu volumio[1199]: info: Loading plugin "volumiodiscovery"... Dec 16 18:28:03 volumio-manu volumio[1199]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 16 18:28:03 volumio-manu volumio[1199]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 16 18:28:03 volumio-manu volumio[1199]: *** WARNING *** For more information see Dec 16 18:28:03 volumio-manu volumio[1199]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 16 18:28:03 volumio-manu volumio[1199]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 16 18:28:03 volumio-manu volumio[1199]: *** WARNING *** For more information see Dec 16 18:28:03 volumio-manu node[1199]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 16 18:28:03 volumio-manu node[1199]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 16 18:28:03 volumio-manu node[1199]: *** WARNING *** For more information see Dec 16 18:28:03 volumio-manu node[1199]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 16 18:28:03 volumio-manu node[1199]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 16 18:28:03 volumio-manu node[1199]: *** WARNING *** For more information see Dec 16 18:28:03 volumio-manu volumio[1199]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 16 18:28:03 volumio-manu volumio[1199]: info: Discovery: Started advertising with name: Volumio Manu Dec 16 18:28:03 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 16 18:28:03 volumio-manu volumio[1199]: info: Loading plugin "spop"... Dec 16 18:28:03 volumio-manu volumio-remote-updater[672]: [2025-12-16 18:28:03] [connect] Successful connection Dec 16 18:28:06 volumio-manu volumio[1199]: info: Loading plugin "outputs"... Dec 16 18:28:06 volumio-manu volumio[1199]: info: Loading plugin "albumart"... Dec 16 18:28:06 volumio-manu volumio[1199]: info: Plugin example_plugin is not enabled Dec 16 18:28:06 volumio-manu volumio[1199]: info: Loading plugin "inputs"... Dec 16 18:28:06 volumio-manu volumio[1199]: info: Loading plugin "updater_comm"... Dec 16 18:28:06 volumio-manu volumio[1199]: info: Plugin mpdemulation is not enabled Dec 16 18:28:06 volumio-manu volumio[1199]: info: Loading plugin "rest_api"... Dec 16 18:28:06 volumio-manu volumio[1199]: info: Loading plugin "websocket"... Dec 16 18:28:06 volumio-manu volumio[1199]: info: Starting Socket.io Server version 1.7.4 Dec 16 18:28:06 volumio-manu volumio[1199]: info: Loading plugin "podcast"... Dec 16 18:28:07 volumio-manu volumio[1346]: Forking 3 albumart workers Dec 16 18:28:07 volumio-manu volumio[1199]: info: ControllerPodcast::constructor Dec 16 18:28:08 volumio-manu systemd[1]: systemd-fsckd.service: Deactivated successfully. Dec 16 18:28:08 volumio-manu volumio[1199]: info: Loading plugin "backup_restore"... Dec 16 18:28:11 volumio-manu volumio[1199]: info: Applying required configuration parameters for plugin backup_restore Dec 16 18:28:11 volumio-manu volumio[1199]: info: Loading plugin "audiophonicsonoff"... Dec 16 18:28:11 volumio-manu systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Dec 16 18:28:11 volumio-manu systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 16 18:28:11 volumio-manu systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 16 18:28:11 volumio-manu upmpdcli[1400]: Could not open config: /tmp/upmpdcli.conf Dec 16 18:28:11 volumio-manu systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Dec 16 18:28:11 volumio-manu systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Dec 16 18:28:13 volumio-manu systemd[1]: systemd-hostnamed.service: Deactivated successfully. Dec 16 18:28:13 volumio-manu volumio[1199]: info: Applying required configuration parameters for plugin audiophonicsonoff Dec 16 18:28:13 volumio-manu volumio[1199]: info: Audiophonics on/off initiated Dec 16 18:28:13 volumio-manu volumio[1199]: info: Loading i18n strings for locale fr Dec 16 18:28:13 volumio-manu volumio[1199]: Updating browse sources language Dec 16 18:28:14 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::initPlayerControls Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:28:16 volumio-manu volumio[1199]: Express server listening on port 3000 Dec 16 18:28:16 volumio-manu volumio[1199]: [Metrics] WebUI: 23s 94.65ms Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreStateMachine::resetVolumioState Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreStateMachine::getcurrentVolume Dec 16 18:28:16 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioRetrievevolume Dec 16 18:28:16 volumio-manu sudo[1412]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 16 18:28:16 volumio-manu volumio[1357]: Starting albumart workers Dec 16 18:28:16 volumio-manu sudo[1410]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 16 18:28:16 volumio-manu sudo[1410]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:16 volumio-manu sudo[1410]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:16 volumio-manu sudo[1412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:16 volumio-manu sudo[1412]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:16 volumio-manu volumio[1358]: Starting albumart workers Dec 16 18:28:17 volumio-manu volumio[1356]: Starting albumart workers Dec 16 18:28:17 volumio-manu volumio[1199]: info: Volumio Network Manager: Network status updated: 1 Dec 16 18:28:17 volumio-manu volumio[1199]: info: VolumeController:: Volume=100 Mute =false Dec 16 18:28:17 volumio-manu volumio[1199]: info: CoreStateMachine::pushState Dec 16 18:28:17 volumio-manu volumio[1199]: info: CorePlayQueue::getTrack 0 Dec 16 18:28:17 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 16 18:28:17 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioPushState Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreStateMachine::updateTrackBlock Dec 16 18:28:18 volumio-manu volumio[1199]: info: CorePlayQueue::getTrackBlock Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioRetrievevolume Dec 16 18:28:18 volumio-manu volumio-remote-updater[672]: [2025-12-16 18:28:18] [connect] Successful connection Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:18 volumio-manu volumio[1199]: info: Reloading queue from file Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreStateMachine::setRepeat null single undefined Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreStateMachine::pushState Dec 16 18:28:18 volumio-manu volumio[1199]: info: CorePlayQueue::getTrack 0 Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioPushState Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreStateMachine::setRandom null Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreStateMachine::pushState Dec 16 18:28:18 volumio-manu volumio[1199]: info: CorePlayQueue::getTrack 0 Dec 16 18:28:18 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioPushState Dec 16 18:28:18 volumio-manu volumio-remote-updater[672]: [2025-12-16 18:28:18] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765906098 101 Dec 16 18:28:18 volumio-manu volumio[1199]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 16 18:28:19 volumio-manu volumio[1199]: info: Setting Device type: Raspberry PI Dec 16 18:28:19 volumio-manu volumio[1199]: info: Completed loading Core Plugins Dec 16 18:28:19 volumio-manu volumio[1199]: info: Preparing to generate the ALSA configuration file Dec 16 18:28:19 volumio-manu volumio[1199]: info: VolumeController:: Volume=100 Mute =false Dec 16 18:28:19 volumio-manu volumio[1199]: info: CoreStateMachine::pushState Dec 16 18:28:19 volumio-manu volumio[1199]: info: CorePlayQueue::getTrack 0 Dec 16 18:28:19 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioPushState Dec 16 18:28:19 volumio-manu volumio[1199]: info: Asound.conf file unchanged, so no further update is needed Dec 16 18:28:19 volumio-manu volumio[1199]: info: Output device has changed, restarting MPD Dec 16 18:28:19 volumio-manu sudo[1443]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 16 18:28:19 volumio-manu sudo[1443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:19 volumio-manu volumio[1199]: info: Output device has changed, restarting Shairport Sync Dec 16 18:28:19 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:19 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:19 volumio-manu sudo[1446]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 16 18:28:19 volumio-manu sudo[1446]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:19 volumio-manu sudo[1446]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:19 volumio-manu volumio[1199]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 16 18:28:19 volumio-manu volumio[1199]: info: ___________ START PLUGINS ___________ Dec 16 18:28:19 volumio-manu sudo[1448]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 16 18:28:19 volumio-manu sudo[1448]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:20 volumio-manu volumio[1199]: info: ControllerMpd::onStart: Initializing MPD Dec 16 18:28:20 volumio-manu volumio[1199]: info: Creating MPD Configuration file Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 16 18:28:20 volumio-manu volumio[1199]: info: [1765906100119] CoreMusicLibrary::Adding element Serveurs Média Dec 16 18:28:20 volumio-manu sudo[1456]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 16 18:28:20 volumio-manu sudo[1456]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:20 volumio-manu systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 18:28:20 volumio-manu systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 16 18:28:20 volumio-manu systemd[1]: Starting mpd.service - Music Player Daemon... Dec 16 18:28:20 volumio-manu sudo[1456]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:20 volumio-manu volumio[1199]: info: UPNP Browser: Client initialized successfully Dec 16 18:28:20 volumio-manu sudo[1459]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 16 18:28:20 volumio-manu sudo[1459]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:20 volumio-manu sudo[1468]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 16 18:28:20 volumio-manu sudo[1468]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 16 18:28:20 volumio-manu sudo[1477]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 16 18:28:20 volumio-manu sudo[1468]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:20 volumio-manu volumio[1199]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:20 volumio-manu volumio[1199]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 16 18:28:20 volumio-manu systemd[1]: mpd.service: Deactivated successfully. Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 16 18:28:20 volumio-manu volumio[1199]: info: [1765906100650] CoreMusicLibrary::Adding element Last_100 Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 18:28:20 volumio-manu systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 16 18:28:20 volumio-manu systemd[1]: mpd.socket: Deactivated successfully. Dec 16 18:28:20 volumio-manu systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 16 18:28:20 volumio-manu systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 16 18:28:20 volumio-manu systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 16 18:28:20 volumio-manu volumio[1199]: info: [1765906100681] CoreMusicLibrary::Adding element Webradio Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 18:28:20 volumio-manu systemd[1]: Starting mpd.service - Music Player Daemon... Dec 16 18:28:20 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 16 18:28:20 volumio-manu volumio[1199]: info: Initializing BBC Radios Dec 16 18:28:20 volumio-manu sudo[1491]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 16 18:28:20 volumio-manu sudo[1491]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 16 18:28:20 volumio-manu sudo[1494]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 16 18:28:20 volumio-manu sudo[1491]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:21 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 16 18:28:21 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:21 volumio-manu volumio[1199]: info: Creating Spotify config file Dec 16 18:28:21 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:21 volumio-manu systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 16 18:28:21 volumio-manu systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 16 18:28:21 volumio-manu systemd[1]: setdatetime-helper.service: Consumed 1.003s CPU time. Dec 16 18:28:23 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 16 18:28:23 volumio-manu volumio[1199]: info: [1765906103408] CoreMusicLibrary::Adding element Podcast Dec 16 18:28:23 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 18:28:23 volumio-manu volumio[1199]: Cannot find translation for source Podcast Dec 16 18:28:23 volumio-manu volumio[1199]: info: Configuring GPIO pins Dec 16 18:28:23 volumio-manu volumio[1199]: info: Soft shutdown GPIO 516 binding... OK Dec 16 18:28:23 volumio-manu volumio[1199]: info: Hardware button GPIO 529 binding... OK Dec 16 18:28:23 volumio-manu volumio[1199]: info: Boot OK GPIO 534 binding... OK Dec 16 18:28:23 volumio-manu volumio[1199]: info: Volumio Calling Home Dec 16 18:28:25 volumio-manu volumio[1199]: info: Discovery: adding 2d4b54dd-672c-4b28-8353-fe66b43ecafd Dec 16 18:28:25 volumio-manu volumio[1199]: info: Discovery: Found device Volumio Manu Dec 16 18:28:25 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioGetState Dec 16 18:28:25 volumio-manu volumio[1199]: info: CorePlayQueue::getTrack 0 Dec 16 18:28:25 volumio-manu volumio[1199]: info: Discovery: this is already registered, 2d4b54dd-672c-4b28-8353-fe66b43ecafd Dec 16 18:28:25 volumio-manu volumio[1199]: info: Discovery: Found device Volumio Manu Dec 16 18:28:25 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioGetState Dec 16 18:28:25 volumio-manu volumio[1199]: info: CorePlayQueue::getTrack 0 Dec 16 18:28:25 volumio-manu volumio[1199]: info: MPD Permissions set Dec 16 18:28:25 volumio-manu volumio[1199]: info: MPD Permissions set Dec 16 18:28:26 volumio-manu volumio[1199]: info: Spotify config file written Dec 16 18:28:26 volumio-manu sudo[1567]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 18:28:26 volumio-manu sudo[1567]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:26 volumio-manu 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 16 18:28:26 volumio-manu 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 16 18:28:26 volumio-manu go-librespot[1569]: go-librespot daemon starting... Dec 16 18:28:26 volumio-manu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:28:26 volumio-manu sudo[1567]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:26 volumio-manu systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Dec 16 18:28:26 volumio-manu systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 16 18:28:26 volumio-manu systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 16 18:28:26 volumio-manu sudo[1443]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:26 volumio-manu volumio[1199]: 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 16 18:28:27 volumio-manu volumio[1199]: info: Volumio called home Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:28:27 volumio-manu volumio[1199]: info: No need to fix Spotify hosts Dec 16 18:28:27 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:27+01:00" level=info msg="running go-librespot 0.4.0" Dec 16 18:28:27 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:27+01:00" level=debug msg="app state loaded" Dec 16 18:28:27 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:27+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+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 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+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 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+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 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=info msg="zeroconf server listening on port 38585" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="obtained new client token: AAAHyS33ohkZ+QmRJq+GBzukyR+uuOb/2o8sXmz1Z4EyOz0Xi+FdkRbIrndOl1au4NnXo3BdSbg7qCf95PWub0jEJiD5NWOkGvUcBvkC07hrsKNk/j0p4TsmxP1SmcS1u+UZ9JF6GjRt47d5Fx+5YCfvAfq/NHvAwjPJE7DsHP10ztuPXzrwZKDaGLdFLYfaLKmKKXpdPRYP5QILlG7e+0/AC3cRW0umZ9hwfbCoqmWE5GFnMglSpBxE" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="completed keyexchange" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="completed challenge" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=info msg="authenticated AP" username="31************************my" Dec 16 18:28:28 volumio-manu mpd[1495]: decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 16 18:28:28 volumio-manu mpd[1495]: output: No 'audio_output' defined in config file Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=info msg="authenticated Login5" username="31************************my" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="initializing zeroconf session" username="31************************my" Dec 16 18:28:28 volumio-manu mpd[1495]: output: Successfully detected a sndio audio device Dec 16 18:28:28 volumio-manu mpd[1495]: zeroconf: No global port, disabling zeroconf Dec 16 18:28:28 volumio-manu systemd[1]: Started mpd.service - Music Player Daemon. Dec 16 18:28:28 volumio-manu sudo[1448]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:28 volumio-manu sudo[1459]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="dealer connection opened" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=trace msg="starting accesspoint recv loop" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=trace msg="starting dealer recv loop" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=trace msg="received accesspoint ping" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 16 18:28:28 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:28+01:00" level=debug msg="received connection id: MGYyYjJlYzktYjJi...QzEwMEIwODBBOA==" Dec 16 18:28:29 volumio-manu volumio[1199]: info: Upmpdcli Daemon Started Dec 16 18:28:29 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:29+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 16 18:28:29 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:29+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 16 18:28:29 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:29+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 16 18:28:29 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:29+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 16 18:28:29 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:29+01:00" level=trace msg="received accesspoint pong ack" Dec 16 18:28:29 volumio-manu volumio[1199]: info: Completed starting Core Plugins Dec 16 18:28:29 volumio-manu volumio[1199]: info: ------------------------------------------- Dec 16 18:28:29 volumio-manu volumio[1199]: info: ----- MyVolumio plugins startup ---- Dec 16 18:28:29 volumio-manu volumio[1199]: info: ------------------------------------------- Dec 16 18:28:29 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 16 18:28:29 volumio-manu volumio[1199]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 16 18:28:29 volumio-manu volumio[1199]: SPOTIFY: BQDPViy7T2i6LDYxgr9RYZ2QOorI10eU_SmBoqQ0PgeCQgqMuyu6dZ2dhkKACym0ONqQeUDOHD7QjOaeBmcG-rAOYpemMNEkuzov3wFzcDZaqYyGJ6sLz3_7bqfE-a6yTVHf6ENpPuT9sJ0L3fbzXRmRfZH9ec1p4J0gPXCPmzJDIOKPL9iv14o3OwYqVd6vgyl2qrt7nANpAlmsH1Y5x-rXiWzhC0EmMO9dbpcrUG9hfvWydkvMtbgBOFJ54XayoNgbt-mwDxZnu1lDuHryKnR0QlAnQlaHWSeeCoe4TQYqdk424Cu_uWwLS0N9 Dec 16 18:28:29 volumio-manu volumio[1199]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 16 18:28:29 volumio-manu volumio[1199]: info: New Spotify access token = BQDPViy7T2i6LDYxgr9RYZ2QOorI10eU_SmBoqQ0PgeCQgqMuyu6dZ2dhkKACym0ONqQeUDOHD7QjOaeBmcG-rAOYpemMNEkuzov3wFzcDZaqYyGJ6sLz3_7bqfE-a6yTVHf6ENpPuT9sJ0L3fbzXRmRfZH9ec1p4J0gPXCPmzJDIOKPL9iv14o3OwYqVd6vgyl2qrt7nANpAlmsH1Y5x-rXiWzhC0EmMO9dbpcrUG9hfvWydkvMtbgBOFJ54XayoNgbt-mwDxZnu1lDuHryKnR0QlAnQlaHWSeeCoe4TQYqdk424Cu_uWwLS0N9 Dec 16 18:28:29 volumio-manu volumio[1199]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 16 18:28:29 volumio-manu volumio[1199]: info: MPD running with PID1495 Dec 16 18:28:29 volumio-manu volumio[1199]: ,establishing connection Dec 16 18:28:29 volumio-manu volumio[1199]: info: Starting Shairport Sync Dec 16 18:28:29 volumio-manu volumio[1199]: info: Starting Shairport Sync Dec 16 18:28:29 volumio-manu volumio[1199]: info: Starting Shairport Sync Dec 16 18:28:29 volumio-manu sudo[1622]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 16 18:28:29 volumio-manu sudo[1622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:29 volumio-manu sudo[1620]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 16 18:28:29 volumio-manu sudo[1624]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 16 18:28:29 volumio-manu sudo[1624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:29 volumio-manu sudo[1620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:29 volumio-manu systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 16 18:28:29 volumio-manu systemd[1]: shairport-sync.service: Deactivated successfully. Dec 16 18:28:29 volumio-manu systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 16 18:28:29 volumio-manu systemd[1]: shairport-sync.service: Consumed 2.085s CPU time. Dec 16 18:28:29 volumio-manu systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 16 18:28:29 volumio-manu systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 16 18:28:29 volumio-manu systemd[1]: shairport-sync.service: Deactivated successfully. Dec 16 18:28:30 volumio-manu sudo[1622]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:30 volumio-manu systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 16 18:28:30 volumio-manu systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 16 18:28:30 volumio-manu sudo[1624]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:30 volumio-manu sudo[1620]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:30 volumio-manu volumio[1199]: error: MPD error: The expression evaluated to a falsy value: Dec 16 18:28:30 volumio-manu volumio[1199]: assert.ok(self.idling) Dec 16 18:28:30 volumio-manu volumio[1199]: error: The expression evaluated to a falsy value: Dec 16 18:28:30 volumio-manu volumio[1199]: assert.ok(self.idling) Dec 16 18:28:30 volumio-manu volumio[1199]: error: MPD error: The expression evaluated to a falsy value: Dec 16 18:28:30 volumio-manu volumio[1199]: assert.ok(self.idling) Dec 16 18:28:30 volumio-manu volumio[1199]: error: The expression evaluated to a falsy value: Dec 16 18:28:30 volumio-manu volumio[1199]: assert.ok(self.idling) Dec 16 18:28:30 volumio-manu volumio[1199]: info: Shairport-Sync Started Dec 16 18:28:30 volumio-manu volumio[1199]: Error adding Membership: Error: addMembership EINVAL Dec 16 18:28:30 volumio-manu volumio[1199]: info: Shairport-Sync Started Dec 16 18:28:30 volumio-manu volumio[1199]: info: Shairport-Sync Started Dec 16 18:28:30 volumio-manu volumio[1199]: error: updateQueue error: null Dec 16 18:28:30 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioGetState Dec 16 18:28:30 volumio-manu volumio[1199]: info: CorePlayQueue::getTrack 0 Dec 16 18:28:31 volumio-manu volumio[1199]: SPOTIFY: User informations: {"country":"FR","display_name":"Théoazerty","email":"rollinmanu@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31gszsn5p2sazmn7axnxuuzuswmy"},"followers":{"href":null,"total":2},"href":"https://api.spotify.com/v1/users/31gszsn5p2sazmn7axnxuuzuswmy","id":"31gszsn5p2sazmn7axnxuuzuswmy","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85ffac796090e7264258a23179","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82ffac796090e7264258a23179","width":64}],"product":"premium","type":"user","uri":"spotify:user:31gszsn5p2sazmn7axnxuuzuswmy"} Dec 16 18:28:31 volumio-manu volumio[1199]: info: Spotify Successfully logged in Dec 16 18:28:31 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 16 18:28:31 volumio-manu volumio[1199]: info: [1765906111311] CoreMusicLibrary::Adding element Spotify Dec 16 18:28:31 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 18:28:31 volumio-manu volumio[1199]: Cannot find translation for source Podcast Dec 16 18:28:31 volumio-manu volumio[1199]: Cannot find translation for source Spotify Dec 16 18:28:32 volumio-manu volumio[1199]: info: go-librespot daemon successfully initialized Dec 16 18:28:32 volumio-manu sudo[1651]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 16 18:28:32 volumio-manu sudo[1651]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:32 volumio-manu sudo[1653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 16 18:28:32 volumio-manu sudo[1653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:32 volumio-manu systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 16 18:28:32 volumio-manu mpd_monitor.sh[1656]: MPD Monitor Service: Starting MPD Monitor Service Dec 16 18:28:32 volumio-manu sudo[1651]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:32 volumio-manu volumio[1199]: info: Successfully started MPD Monitor Dec 16 18:28:32 volumio-manu systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 16 18:28:32 volumio-manu systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 16 18:28:32 volumio-manu systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 16 18:28:32 volumio-manu systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 16 18:28:32 volumio-manu mpd_monitor.sh[1660]: MPD Monitor Service: Starting MPD Monitor Service Dec 16 18:28:32 volumio-manu sudo[1653]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:32 volumio-manu volumio[1199]: info: Successfully started MPD Monitor Dec 16 18:28:34 volumio-manu mpd[1495]: exception: No database Dec 16 18:28:34 volumio-manu mpd[1495]: exception: No database Dec 16 18:28:34 volumio-manu volumio[1199]: error: Failed LSINFO: Error: [50@0] {lsinfo} No database Dec 16 18:28:34 volumio-manu mpd[1495]: exception: No database Dec 16 18:28:35 volumio-manu volumio[1199]: info: Initializing connection to go-librespot Websocket Dec 16 18:28:35 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:35+01:00" level=debug msg="new websocket client" Dec 16 18:28:35 volumio-manu volumio[1199]: info: Connection to go-librespot Websocket established Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 16 18:28:38 volumio-manu volumio[1199]: info: Adding plugin bluetooth to MyMusic Plugins Dec 16 18:28:38 volumio-manu volumio[1199]: info: Adding plugin multiroom to MyMusic Plugins Dec 16 18:28:38 volumio-manu volumio[1199]: info: Adding plugin metavolumio to MyMusic Plugins Dec 16 18:28:38 volumio-manu volumio[1199]: info: Adding plugin cd_controller to MyMusic Plugins Dec 16 18:28:38 volumio-manu volumio[1199]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 16 18:28:38 volumio-manu volumio[1199]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 16 18:28:38 volumio-manu volumio[1199]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 16 18:28:38 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 16 18:28:46 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 16 18:28:46 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 16 18:28:46 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:46 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:46 volumio-manu volumio[1199]: info: Starting MyVolumio Remote Streaming Endpoints Dec 16 18:28:46 volumio-manu volumio[1199]: info: MyVolumio login type: Token Dec 16 18:28:47 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 16 18:28:47 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 16 18:28:47 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:47+01:00" level=debug msg="handling transfer player command from 41628da12dfc09be96db3a482766cd2de4d10126" Dec 16 18:28:48 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:48+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:4BUUdiNX3bIWsAWb1xuz5B" Dec 16 18:28:48 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:48+01:00" level=trace msg="fetched new page 0 with 281 items (list: 281)" uri="spotify:playlist:4BUUdiNX3bIWsAWb1xuz5B" Dec 16 18:28:48 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:48+01:00" level=debug msg="loading track (paused: true, position: 2564ms)" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:48 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:48+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 16 18:28:48 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:48+01:00" level=trace msg="emitting websocket event: will_play" Dec 16 18:28:48 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:48+01:00" level=debug msg="selected format OGG_VORBIS_320 (63a2710aff3af0db68a11995bb20b1840f41d972)" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:48 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:48+01:00" level=debug msg="requested aes key for file 63a2710aff3af0db68a11995bb20b1840f41d972, gid: 2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1302" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu upmpdcli[1692]: writing RSA key Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="fetched first chunk of 15, total size is 7589393 bytes" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=trace msg="seek to 2564ms (diff: 118ms, samples: 113072, bytes: 101509)" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="created new output device" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=info msg="loaded track \"INCOGNITO\" (paused: true, position: 2564ms, duration: 158776ms, prefetched: false)" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=trace msg="emitting websocket event: metadata" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=trace msg="emitting websocket event: active" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="sending successful reply for dealer request" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=trace msg="emitting websocket event: paused" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="handling resume player command from 41628da12dfc09be96db3a482766cd2de4d10126" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=trace msg="seek to 2564ms (diff: 118ms, samples: 113072, bytes: 101509)" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="resume track at 2446ms" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=trace msg="scheduling prefetch in 126s" Dec 16 18:28:50 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:50+01:00" level=debug msg="sending successful reply for dealer request" Dec 16 18:28:51 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:51+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 16 18:28:51 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:51+01:00" level=trace msg="emitting websocket event: playing" Dec 16 18:28:51 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:51+01:00" level=debug msg="update volume requested to 65535/65535" Dec 16 18:28:51 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:51+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 16 18:28:51 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:51+01:00" level=trace msg="emitting websocket event: volume" Dec 16 18:28:53 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 16 18:28:53 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 16 18:28:53 volumio-manu volumio[1199]: info: Streaming services startup Dec 16 18:28:53 volumio-manu volumio[1199]: info: Starting Streaming Daemon Dec 16 18:28:53 volumio-manu volumio[1199]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 16 18:28:53 volumio-manu sudo[1703]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 16 18:28:53 volumio-manu volumio[1199]: info: Getting Spotify volume Dec 16 18:28:53 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 16 18:28:53 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:28:53 volumio-manu volumio[1199]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 16 18:28:53 volumio-manu sudo[1703]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:28:53 volumio-manu volumio[1199]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4BUUdiNX3bIWsAWb1xuz5B","uri":"spotify:track:2uoKEakNdnvTGA5YOgQKZx","play_origin":"playlist"}} Dec 16 18:28:53 volumio-manu volumio[1199]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2uoKEakNdnvTGA5YOgQKZx","name":"INCOGNITO","artist_names":["GIMS","R2"],"album_name":"INCOGNITO","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ce707c8e7e61828c52156e08","position":2564,"duration":158776,"release_date":"year:2025 month:12 day:12","track_number":1,"disc_number":1}} Dec 16 18:28:53 volumio-manu volumio[1199]: SPOTIFY: received: {"type":"active","data":null} Dec 16 18:28:53 volumio-manu volumio[1199]: info: Aligning Spotify Volume to Volumio Volume Dec 16 18:28:53 volumio-manu volumio[1199]: info: CoreCommandRouter::volumioGetState Dec 16 18:28:53 volumio-manu volumio[1199]: info: CorePlayQueue::getTrack 0 Dec 16 18:28:53 volumio-manu volumio[1199]: info: Setting Spotify Volume from Volumio: 100 Dec 16 18:28:53 volumio-manu volumio[1199]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:4BUUdiNX3bIWsAWb1xuz5B","uri":"spotify:track:2uoKEakNdnvTGA5YOgQKZx","play_origin":"playlist"}} Dec 16 18:28:53 volumio-manu volumio[1199]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 16 18:28:53 volumio-manu sudo[1703]: pam_unix(sudo:session): session closed for user root Dec 16 18:28:54 volumio-manu volumio[1199]: TypeError: Cannot read properties of undefined (reading 'service') Dec 16 18:28:54 volumio-manu volumio[1199]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 16 18:28:54 volumio-manu volumio[1199]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Dec 16 18:28:54 volumio-manu volumio[1199]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 16 18:28:54 volumio-manu volumio[1199]: at WebSocket.emit (node:events:514:28) Dec 16 18:28:54 volumio-manu volumio[1199]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 16 18:28:54 volumio-manu volumio[1199]: at Receiver.emit (node:events:514:28) Dec 16 18:28:54 volumio-manu volumio[1199]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 16 18:28:54 volumio-manu volumio[1199]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 16 18:28:54 volumio-manu volumio[1199]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 16 18:28:54 volumio-manu volumio[1199]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 16 18:28:54 volumio-manu volumio[1199]: at writeOrBuffer (node:internal/streams/writable:399:12) Dec 16 18:28:54 volumio-manu volumio[1199]: at _write (node:internal/streams/writable:340:10) Dec 16 18:28:54 volumio-manu volumio[1199]: at Writable.write (node:internal/streams/writable:344:10) Dec 16 18:28:54 volumio-manu volumio[1199]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 16 18:28:54 volumio-manu volumio[1199]: at Socket.emit (node:events:514:28) Dec 16 18:28:54 volumio-manu volumio[1199]: at addChunk (node:internal/streams/readable:343:12) Dec 16 18:28:54 volumio-manu volumio[1199]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 16 18:28:58 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:58+01:00" level=trace msg="sent dealer ping" Dec 16 18:28:58 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:58+01:00" level=trace msg="received dealer pong" Dec 16 18:28:59 volumio-manu go-librespot[1570]: time="2025-12-16T18:28:59+01:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:2uoKEakNdnvTGA5YOgQKZx" Dec 16 18:28:59 volumio-manu sudo[1726]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-16 18:27' Dec 16 18:28:59 volumio-manu sudo[1726]: 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"