-- Logs begin at Sun 2025-10-26 10:53:42 UTC, end at Sun 2025-10-26 10:55:58 UTC. -- Oct 26 10:54:21 volumio systemd-timedated[772]: Changed local time to Sun Oct 26 10:54:21 2025 Oct 26 10:54:21 volumio sudo[770]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:21 volumio volumio-time-update[477]: volumio-time-update-util: System time updated successfully. Oct 26 10:54:21 volumio systemd[1]: Started Volumio Time Update Utility. Oct 26 10:54:21 volumio systemd[1]: Reached target Multi-User System. Oct 26 10:54:21 volumio systemd[1]: Reached target Graphical Interface. Oct 26 10:54:21 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Oct 26 10:54:21 volumio systemd[1]: Starting Daily apt download activities... Oct 26 10:54:21 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Oct 26 10:54:21 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Oct 26 10:54:21 volumio systemd[1]: Started Music Player Daemon. Oct 26 10:54:21 volumio mpd_monitor.sh[472]: MPD Monitor Service: MPD restarted due to no mpc output. Oct 26 10:54:22 volumio volumio-remote-updater[491]: [2025-10-26 10:54:22] [connect] Successful connection Oct 26 10:54:22 volumio volumio[676]: info: MYVOLUMIO Environment detected Oct 26 10:54:22 volumio volumio[676]: info: Plugin folders cleanup Oct 26 10:54:22 volumio volumio[676]: info: Scanning into folder /volumio/app/plugins/ Oct 26 10:54:22 volumio volumio[676]: info: Scanning category audio_interface Oct 26 10:54:22 volumio volumio[676]: info: Scanning category miscellanea Oct 26 10:54:22 volumio volumio[676]: info: Scanning category music_service Oct 26 10:54:22 volumio volumio[676]: info: Scanning category plugins.json Oct 26 10:54:22 volumio volumio[676]: info: Scanning category system_controller Oct 26 10:54:22 volumio volumio[676]: info: Scanning category user_interface Oct 26 10:54:22 volumio volumio[676]: info: Scanning into folder /data/plugins/ Oct 26 10:54:22 volumio volumio[676]: info: Scanning category music_service Oct 26 10:54:22 volumio volumio[676]: info: Plugin folders cleanup completed Oct 26 10:54:22 volumio volumio[676]: info: ------------------------------------------- Oct 26 10:54:22 volumio volumio[676]: info: ----- Core plugins startup ---- Oct 26 10:54:22 volumio volumio[676]: info: ------------------------------------------- Oct 26 10:54:22 volumio volumio[676]: info: Loading plugins from folder /volumio/app/plugins/ Oct 26 10:54:22 volumio volumio[676]: info: Adding plugin upnp to MyMusic Plugins Oct 26 10:54:22 volumio volumio[676]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 26 10:54:22 volumio volumio[676]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 26 10:54:22 volumio volumio[676]: info: Loading plugins from folder /data/plugins/ Oct 26 10:54:22 volumio volumio[676]: info: Loading plugin "system"... Oct 26 10:54:23 volumio volumio[676]: info: Loading plugin "appearance"... Oct 26 10:54:26 volumio systemd[1]: apt-daily.service: Succeeded. Oct 26 10:54:26 volumio systemd[1]: Started Daily apt download activities. Oct 26 10:54:26 volumio systemd[1]: Startup finished in 14.890s (kernel) + 24.496s (userspace) = 39.386s. Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "network"... Oct 26 10:54:26 volumio volumio[676]: info: Refreshing Cached IP Addresses Oct 26 10:54:26 volumio sudo[831]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 10:54:26 volumio sudo[831]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:26 volumio sudo[833]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 10:54:26 volumio sudo[831]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:26 volumio sudo[833]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "services"... Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "alsa_controller"... Oct 26 10:54:26 volumio sudo[833]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:26 volumio sudo[841]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 26 10:54:26 volumio sudo[841]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:26 volumio sudo[841]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:26 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "wizard"... Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "networkfs"... Oct 26 10:54:26 volumio volumio[676]: info: Starting Udev Watcher for removable devices Oct 26 10:54:26 volumio sudo[863]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Music,password=MUSI_musi2,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.35/music /mnt/NAS/DS1520 Oct 26 10:54:26 volumio sudo[863]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:26 volumio volumio[676]: info: Ignoring mount for partition: boot Oct 26 10:54:26 volumio volumio[676]: info: Ignoring mount for partition: volumio Oct 26 10:54:26 volumio volumio[676]: info: Ignoring mount for partition: volumio_data Oct 26 10:54:26 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "volumio_command_line_client"... Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "upnp"... Oct 26 10:54:26 volumio volumio[676]: info: [1761476066967] Starting Upmpd Daemon Oct 26 10:54:26 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "my_music"... Oct 26 10:54:26 volumio volumio[676]: info: Loading plugin "mpd"... Oct 26 10:54:27 volumio kernel: Key type cifs.spnego registered Oct 26 10:54:27 volumio kernel: Key type cifs.idmap registered Oct 26 10:54:27 volumio 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. Oct 26 10:54:27 volumio kernel: CIFS: Attempting to mount //192.168.0.35/music Oct 26 10:54:27 volumio kernel: cryptd: max_cpu_qlen set to 1000 Oct 26 10:54:27 volumio sudo[863]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:28 volumio volumio[676]: info: Loading plugin "upnp_browser"... Oct 26 10:54:28 volumio volumio[676]: info: Loading plugin "alarm-clock"... Oct 26 10:54:29 volumio volumio[676]: info: Loading plugin "airplay_emulation"... Oct 26 10:54:29 volumio volumio[676]: info: Starting Shairport Sync Oct 26 10:54:29 volumio volumio[676]: info: Loading plugin "last_100"... Oct 26 10:54:29 volumio volumio[676]: info: Loading plugin "webradio"... Oct 26 10:54:29 volumio volumio[676]: info: Loading plugin "i2s_dacs"... Oct 26 10:54:29 volumio volumio[676]: info: Loading plugin "volumiodiscovery"... Oct 26 10:54:29 volumio volumio[676]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 10:54:29 volumio volumio[676]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 10:54:29 volumio volumio[676]: *** WARNING *** For more information see Oct 26 10:54:29 volumio node[676]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 10:54:29 volumio volumio[676]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 10:54:29 volumio volumio[676]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 10:54:29 volumio volumio[676]: *** WARNING *** For more information see Oct 26 10:54:29 volumio node[676]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 10:54:29 volumio node[676]: *** WARNING *** For more information see Oct 26 10:54:29 volumio node[676]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 10:54:29 volumio node[676]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 10:54:29 volumio node[676]: *** WARNING *** For more information see Oct 26 10:54:29 volumio volumio[676]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 26 10:54:29 volumio volumio[676]: info: Discovery: Started advertising with name: Volumio Oct 26 10:54:29 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 10:54:29 volumio volumio[676]: info: Loading plugin "spop"... Oct 26 10:54:33 volumio volumio[676]: info: Loading plugin "outputs"... Oct 26 10:54:33 volumio volumio[676]: info: Loading plugin "albumart"... Oct 26 10:54:33 volumio volumio[676]: info: Plugin example_plugin is not enabled Oct 26 10:54:33 volumio volumio[676]: info: Loading plugin "inputs"... Oct 26 10:54:33 volumio volumio[676]: info: Loading plugin "updater_comm"... Oct 26 10:54:33 volumio volumio[676]: info: Plugin mpdemulation is not enabled Oct 26 10:54:33 volumio volumio[676]: info: Loading plugin "rest_api"... Oct 26 10:54:33 volumio volumio[676]: info: Loading plugin "websocket"... Oct 26 10:54:33 volumio volumio[676]: info: Starting Socket.io Server version 2.3.0 Oct 26 10:54:33 volumio volumio[676]: info: Plugin minidlna is not enabled Oct 26 10:54:33 volumio volumio[676]: info: Loading i18n strings for locale fr Oct 26 10:54:33 volumio volumio[676]: Updating browse sources language Oct 26 10:54:33 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:54:33 volumio volumio[676]: Forking 3 albumart workers Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::initPlayerControls Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 10:54:34 volumio volumio[676]: Express server listening on port 3000 Oct 26 10:54:34 volumio volumio[676]: [Metrics] WebUI: 16s 765.84ms Oct 26 10:54:34 volumio volumio[676]: info: CoreStateMachine::resetVolumioState Oct 26 10:54:34 volumio volumio[676]: info: CoreStateMachine::getcurrentVolume Oct 26 10:54:34 volumio volumio[676]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 10:54:34 volumio volumio[676]: info: Volumio Network Manager: Network status updated: 1 Oct 26 10:54:34 volumio volumio[676]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Oct 26 10:54:34 volumio volumio[676]: wlan0 Interface doesn't support scanning. Oct 26 10:54:34 volumio volumio[676]: info: Cannot use regular scanning, forcing with ap-force Oct 26 10:54:34 volumio sudo[940]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Oct 26 10:54:34 volumio sudo[940]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:34 volumio sudo[940]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:34 volumio volumio[676]: command failed: No such device (-19) Oct 26 10:54:34 volumio volumio[676]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Oct 26 10:54:34 volumio volumio[676]: command failed: No such device (-19) Oct 26 10:54:35 volumio volumio[676]: verbose: New Socket.io Connection to 192.168.0.51 from 192.168.0.33 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Oct 26 10:54:35 volumio volumio[676]: verbose: New Socket.io Connection to 192.168.0.51 from 192.168.0.33 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Oct 26 10:54:35 volumio volumio[676]: verbose: New Socket.io Connection to 192.168.0.51 from 192.168.0.33 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Oct 26 10:54:35 volumio volumio[676]: Unable to parse: Oct 26 10:54:35 volumio volumio[676]: Simple mixer control 'Master',0 Oct 26 10:54:35 volumio volumio[676]: Capabilities: volume volume-joined Oct 26 10:54:35 volumio volumio[676]: Playback channels: Mono Oct 26 10:54:35 volumio volumio[676]: Capture channels: Mono Oct 26 10:54:35 volumio volumio[676]: Limits: 0 - 248 Oct 26 10:54:35 volumio volumio[676]: Mono: 127 [51%] Oct 26 10:54:35 volumio volumio[676]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Oct 26 10:54:35 volumio volumio[676]: info: Reloading queue from file Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:54:35 volumio volumio[676]: info: CoreStateMachine::setRepeat false single undefined Oct 26 10:54:35 volumio volumio[676]: info: CoreStateMachine::pushState Oct 26 10:54:35 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::volumioPushState Oct 26 10:54:35 volumio volumio[676]: info: CoreStateMachine::setRandom true Oct 26 10:54:35 volumio volumio[676]: info: CoreStateMachine::pushState Oct 26 10:54:35 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::volumioPushState Oct 26 10:54:35 volumio volumio[676]: info: Setting Device type: Raspberry PI Oct 26 10:54:35 volumio volumio[676]: info: Completed loading Core Plugins Oct 26 10:54:35 volumio volumio[676]: info: Preparing to generate the ALSA configuration file Oct 26 10:54:35 volumio volumio[676]: Unable to parse: Oct 26 10:54:35 volumio volumio[676]: Simple mixer control 'Master',0 Oct 26 10:54:35 volumio volumio[676]: Capabilities: volume volume-joined Oct 26 10:54:35 volumio volumio[676]: Playback channels: Mono Oct 26 10:54:35 volumio volumio[676]: Capture channels: Mono Oct 26 10:54:35 volumio volumio[676]: Limits: 0 - 248 Oct 26 10:54:35 volumio volumio[676]: Mono: 127 [51%] Oct 26 10:54:35 volumio volumio[676]: info: VolumeController:: Volume=undefined Mute =false Oct 26 10:54:35 volumio volumio[676]: info: CoreStateMachine::pushState Oct 26 10:54:35 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::volumioPushState Oct 26 10:54:35 volumio volumio[676]: info: CoreStateMachine::updateTrackBlock Oct 26 10:54:35 volumio volumio[676]: info: CorePlayQueue::getTrackBlock Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 10:54:35 volumio volumio[676]: Unable to parse: Oct 26 10:54:35 volumio volumio[676]: Simple mixer control 'Master',0 Oct 26 10:54:35 volumio volumio[676]: Capabilities: volume volume-joined Oct 26 10:54:35 volumio volumio[676]: Playback channels: Mono Oct 26 10:54:35 volumio volumio[676]: Capture channels: Mono Oct 26 10:54:35 volumio volumio[676]: Limits: 0 - 248 Oct 26 10:54:35 volumio volumio[676]: Mono: 127 [51%] Oct 26 10:54:35 volumio volumio[676]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Oct 26 10:54:35 volumio volumio[676]: info: Asound.conf file unchanged, so no further update is needed Oct 26 10:54:35 volumio volumio[676]: info: Output device has changed, restarting MPD Oct 26 10:54:35 volumio volumio[676]: info: Output device has changed, restarting Shairport Sync Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:35 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:54:35 volumio sudo[953]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 10:54:35 volumio sudo[953]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:35 volumio volumio[676]: Starting albumart workers Oct 26 10:54:35 volumio sudo[953]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:36 volumio sudo[955]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 10:54:36 volumio sudo[955]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:36 volumio volumio[676]: Starting albumart workers Oct 26 10:54:36 volumio volumio[676]: Starting albumart workers Oct 26 10:54:36 volumio volumio[676]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 10:54:36 volumio volumio[676]: info: ___________ START PLUGINS ___________ Oct 26 10:54:36 volumio systemd[1]: Stopping Music Player Daemon... Oct 26 10:54:36 volumio volumio[676]: info: ControllerMpd::onStart: Initializing MPD Oct 26 10:54:36 volumio volumio[676]: info: Creating MPD Configuration file Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 10:54:36 volumio volumio[676]: info: [1761476076228] CoreMusicLibrary::Adding element Serveurs Média Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:54:36 volumio sudo[964]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 10:54:36 volumio sudo[964]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:36 volumio sudo[962]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 10:54:36 volumio sudo[962]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:36 volumio sudo[962]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:54:36 volumio volumio[676]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:54:36 volumio volumio[676]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 10:54:36 volumio volumio[676]: info: [1761476076834] CoreMusicLibrary::Adding element Last_100 Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 10:54:36 volumio volumio[676]: info: [1761476076849] CoreMusicLibrary::Adding element Webradio Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:54:36 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:54:36 volumio volumio[676]: info: Initializing BBC Radios Oct 26 10:54:36 volumio systemd[1]: mpd.service: Succeeded. Oct 26 10:54:36 volumio systemd[1]: Stopped Music Player Daemon. Oct 26 10:54:37 volumio systemd[1]: Starting Music Player Daemon... Oct 26 10:54:37 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:54:37 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:54:37 volumio systemd[1]: systemd-fsckd.service: Succeeded. Oct 26 10:54:37 volumio volumio[676]: info: Creating Spotify config file Oct 26 10:54:37 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:37 volumio sudo[989]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 10:54:37 volumio sudo[989]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:37 volumio volumio-remote-updater[491]: [2025-10-26 10:54:37] [connect] Successful connection Oct 26 10:54:37 volumio sudo[989]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:37 volumio volumio[676]: info: Volumio Calling Home Oct 26 10:54:38 volumio volumio[676]: info: Discovery: adding 29c73bf8-e642-46f5-8a40-11aaf85d9de1 Oct 26 10:54:38 volumio volumio[676]: info: Discovery: Found device Volumio Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:54:38 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:38 volumio volumio[676]: info: MPD Permissions set Oct 26 10:54:38 volumio volumio[676]: info: MPD Permissions set Oct 26 10:54:38 volumio volumio[676]: Unable to parse: Oct 26 10:54:38 volumio volumio[676]: Simple mixer control 'Master',0 Oct 26 10:54:38 volumio volumio[676]: Capabilities: volume volume-joined Oct 26 10:54:38 volumio volumio[676]: Playback channels: Mono Oct 26 10:54:38 volumio volumio[676]: Capture channels: Mono Oct 26 10:54:38 volumio volumio[676]: Limits: 0 - 248 Oct 26 10:54:38 volumio volumio[676]: Mono: 127 [51%] Oct 26 10:54:38 volumio volumio[676]: info: VolumeController:: Volume=undefined Mute =false Oct 26 10:54:38 volumio sudo[1012]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 10:54:38 volumio volumio[676]: info: CoreStateMachine::pushState Oct 26 10:54:38 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::volumioPushState Oct 26 10:54:38 volumio sudo[1014]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 10:54:38 volumio sudo[1012]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:38 volumio sudo[1014]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:38 volumio sudo[1012]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:38 volumio sudo[1014]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:38 volumio volumio-remote-updater[491]: [2025-10-26 10:54:38] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1761476077 101 Oct 26 10:54:38 volumio volumio[676]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 4 Oct 26 10:54:38 volumio volumio[676]: info: Volumio called home Oct 26 10:54:38 volumio volumio[676]: info: Spotify config file written Oct 26 10:54:38 volumio sudo[1036]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 26 10:54:38 volumio sudo[1036]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:38 volumio volumio[676]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 26 10:54:38 volumio systemd[1]: Started go-librespot Daemon. Oct 26 10:54:38 volumio go-librespot[1038]: go-librespot daemon starting... Oct 26 10:54:38 volumio sudo[1036]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:38 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:39 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:54:39 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:54:39 volumio volumio[676]: info: No need to fix Spotify hosts Oct 26 10:54:39 volumio volumio[676]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 10:54:39 volumio volumio[676]: SPOTIFY: BQDEJ6ifU06NEjCn1F7ifZQWPIuYFJTxViCqIKHo0dTrumtfNWBgaX3CjAvVxWAeFDWlbI-GT8J4MS4DHrjYxvn-EueoLkddAZiqkhsHZaFLuWaQHog6f2BX2fsjlAQtSuKii-EjRwR6t8Acxd5hYuSSVP9kTfVIZG2lEoP9KP-osPJNiV8L_VTGdNZBGnskEMGwHvFrbngr576V_3RvXSvTcMeG-EOz2s7uaFzMf3ydFU_NggDRuvJqesjiHeq91Mq4lDcHMpPgaQ7ZcKy0exDZfno Oct 26 10:54:39 volumio volumio[676]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 10:54:39 volumio volumio[676]: info: New Spotify access token = BQDEJ6ifU06NEjCn1F7ifZQWPIuYFJTxViCqIKHo0dTrumtfNWBgaX3CjAvVxWAeFDWlbI-GT8J4MS4DHrjYxvn-EueoLkddAZiqkhsHZaFLuWaQHog6f2BX2fsjlAQtSuKii-EjRwR6t8Acxd5hYuSSVP9kTfVIZG2lEoP9KP-osPJNiV8L_VTGdNZBGnskEMGwHvFrbngr576V_3RvXSvTcMeG-EOz2s7uaFzMf3ydFU_NggDRuvJqesjiHeq91Mq4lDcHMpPgaQ7ZcKy0exDZfno Oct 26 10:54:39 volumio volumio[676]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 26 10:54:39 volumio volumio[676]: info: Starting Shairport Sync Oct 26 10:54:39 volumio volumio[676]: info: Starting Shairport Sync Oct 26 10:54:39 volumio sudo[1054]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 10:54:39 volumio sudo[1054]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:39 volumio volumio[676]: info: Starting Shairport Sync Oct 26 10:54:39 volumio sudo[1056]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 10:54:39 volumio sudo[1056]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:39 volumio go-librespot[1038]: time="2025-10-26T10:54:39Z" level=info msg="running go-librespot 0.3.2" Oct 26 10:54:39 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 10:54:39 volumio go-librespot[1038]: time="2025-10-26T10:54:39Z" level=debug msg="app state loaded" Oct 26 10:54:39 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 26 10:54:39 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 10:54:39 volumio go-librespot[1038]: time="2025-10-26T10:54:39Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 10:54:39 volumio sudo[1059]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 26 10:54:39 volumio sudo[1062]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 10:54:39 volumio sudo[1059]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:39 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 10:54:39 volumio sudo[1062]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:39 volumio sudo[1054]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:39 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:54:39 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:39 volumio volumio[676]: info: Shairport-Sync Started Oct 26 10:54:39 volumio volumio[676]: Error adding Membership: Error: addMembership EINVAL Oct 26 10:54:40 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Oct 26 10:54:40 volumio sudo[1059]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:40 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 10:54:40 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 26 10:54:40 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 10:54:40 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 10:54:40 volumio sudo[1056]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:40 volumio sudo[1062]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:40 volumio volumio[676]: info: Upmpdcli Daemon Started Oct 26 10:54:40 volumio volumio[676]: info: Shairport-Sync Started Oct 26 10:54:40 volumio volumio[676]: info: Shairport-Sync Started Oct 26 10:54:40 volumio volumio[676]: SPOTIFY: User informations: {"country":"FR","display_name":"alfique","email":"alfique@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/alfique"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/alfique","id":"alfique","images":[],"product":"premium","type":"user","uri":"spotify:user:alfique"} Oct 26 10:54:40 volumio volumio[676]: info: Spotify Successfully logged in Oct 26 10:54:40 volumio volumio[676]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 10:54:40 volumio volumio[676]: info: [1761476080297] CoreMusicLibrary::Adding element Spotify Oct 26 10:54:40 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:54:40 volumio volumio[676]: Cannot find translation for source Spotify Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" 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]" Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" 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]" Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" 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]" Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" level=info msg="zeroconf server listening on port 43701" Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" level=debug msg="obtained new client token: AABghQ/w9Oa36mGz32uU0GTNAljOW3e+FowRABGO25cN7Iqb19twDPY01qcLX44qI892EdDPLaxI9N7Ib5mMIkmS66BPxw4Stm5u2DBrS1ipV86fURLrC9U1qG9HP6eyy/ut0SkXF1DLbhmPoNhJTqjTHkYDMw0TKZNOxl8UgL8sCg8FRHUWE/V9r7PqmLqLIPmY3a0UHv9jFU0Pgl8VcPfsa30RKfHbPlaCSNYz8ytr3HJjB9KNp8w=" Oct 26 10:54:40 volumio sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 10:54:40 volumio sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:40 volumio sudo[1075]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:40 volumio sudo[1077]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 10:54:40 volumio sudo[1077]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 10:54:40 volumio sudo[1077]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" level=debug msg="completed keyexchange" Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" level=debug msg="completed challenge" Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" level=info msg="authenticated AP" username="al***ue" Oct 26 10:54:40 volumio volumio[676]: verbose: New Socket.io Connection to 192.168.0.51 from 192.168.0.33 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Oct 26 10:54:40 volumio mpd[999]: Oct 26 10:54 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" level=info msg="authenticated Login5" username="al***ue" Oct 26 10:54:40 volumio go-librespot[1038]: time="2025-10-26T10:54:40Z" level=debug msg="initializing zeroconf session" username="al***ue" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=debug msg="dealer connection opened" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=trace msg="starting accesspoint recv loop" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=trace msg="starting dealer recv loop" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=trace msg="received accesspoint ping" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=debug msg="received connection id: ODcwNTQ3YmMtNGJj...M0FBNDI5RDEyNQ==" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=trace msg="received accesspoint pong ack" Oct 26 10:54:41 volumio go-librespot[1038]: time="2025-10-26T10:54:41Z" level=debug msg="put connect state because NEW_DEVICE" Oct 26 10:54:41 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 10:54:41 volumio sudo[1085]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 10:54:41 volumio sudo[1085]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:41 volumio sudo[1085]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:41 volumio sudo[1087]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 10:54:41 volumio sudo[1087]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:41 volumio sudo[1087]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:42 volumio volumio[676]: verbose: New Socket.io Connection to 192.168.0.51 from 192.168.0.33 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Oct 26 10:54:42 volumio volumio[676]: info: go-librespot daemon successfully initialized Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::volumioGetVisibleSources Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:54:42 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 26 10:54:42 volumio volumio[676]: info: Received Get System Info Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 10:54:42 volumio volumio[676]: info: Discovery: Getting this device information Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:54:42 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:54:42 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:42 volumio volumio[676]: info: Listing playlists Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 26 10:54:42 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 10:54:44 volumio systemd[1]: Started Music Player Daemon. Oct 26 10:54:44 volumio volumio[676]: Upnp client error: Error: This socket has been ended by the other party Oct 26 10:54:44 volumio sudo[964]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:44 volumio sudo[955]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:44 volumio volumio[676]: info: Completed starting Core Plugins Oct 26 10:54:44 volumio volumio[676]: info: ------------------------------------------- Oct 26 10:54:44 volumio volumio[676]: info: ----- MyVolumio plugins startup ---- Oct 26 10:54:44 volumio volumio[676]: info: ------------------------------------------- Oct 26 10:54:44 volumio volumio[676]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 26 10:54:44 volumio volumio[676]: error: MPD error: The expression evaluated to a falsy value: Oct 26 10:54:44 volumio volumio[676]: assert.ok(self.idling) Oct 26 10:54:44 volumio volumio[676]: error: The expression evaluated to a falsy value: Oct 26 10:54:44 volumio volumio[676]: assert.ok(self.idling) Oct 26 10:54:44 volumio volumio[676]: info: MPD running with PID999 Oct 26 10:54:44 volumio volumio[676]: ,establishing connection Oct 26 10:54:44 volumio volumio[676]: error: MPD error: The expression evaluated to a falsy value: Oct 26 10:54:44 volumio volumio[676]: assert.ok(self.idling) Oct 26 10:54:44 volumio volumio[676]: error: The expression evaluated to a falsy value: Oct 26 10:54:44 volumio volumio[676]: assert.ok(self.idling) Oct 26 10:54:44 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 26 10:54:44 volumio volumio[676]: info: Received Get System Info Oct 26 10:54:44 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 10:54:44 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 10:54:44 volumio volumio[676]: info: Discovery: Getting this device information Oct 26 10:54:44 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:54:44 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:44 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 10:54:44 volumio volumio[676]: info: VolumeController::SetAlsaVolume0 Oct 26 10:54:44 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 26 10:54:44 volumio volumio[676]: info: CoreStateMachine::pushState Oct 26 10:54:44 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:44 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:54:44 volumio volumio[676]: info: CoreCommandRouter::volumioPushState Oct 26 10:54:44 volumio volumio[676]: error: updateQueue error: null Oct 26 10:54:44 volumio volumio[1069]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 26 10:54:45 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Oct 26 10:54:45 volumio volumio[676]: info: Initializing connection to go-librespot Websocket Oct 26 10:54:45 volumio go-librespot[1038]: time="2025-10-26T10:54:45Z" level=debug msg="new websocket client" Oct 26 10:54:45 volumio volumio[676]: info: Connection to go-librespot Websocket established Oct 26 10:54:45 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 26 10:54:45 volumio volumio[676]: info: Received Get System Info Oct 26 10:54:45 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 10:54:45 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 10:54:45 volumio volumio[676]: info: Discovery: Getting this device information Oct 26 10:54:45 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:54:45 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:45 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 10:54:46 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Oct 26 10:54:46 volumio volumio[1069]: ......++++ Oct 26 10:54:48 volumio volumio[676]: info: Getting Spotify volume Oct 26 10:54:48 volumio volumio[676]: info: Spotify volume: 100 Oct 26 10:54:48 volumio volumio[676]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 26 10:54:48 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:54:48 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:54:51 volumio systemd[1]: systemd-timedated.service: Succeeded. Oct 26 10:54:52 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 26 10:54:52 volumio volumio[676]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 26 10:54:52 volumio volumio[676]: info: Adding plugin bluetooth to MyMusic Plugins Oct 26 10:54:53 volumio volumio[676]: info: Adding plugin multiroom to MyMusic Plugins Oct 26 10:54:53 volumio volumio[676]: info: Adding plugin metavolumio to MyMusic Plugins Oct 26 10:54:53 volumio volumio[676]: info: Adding plugin cd_controller to MyMusic Plugins Oct 26 10:54:53 volumio volumio[676]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 26 10:54:53 volumio volumio[676]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 26 10:54:53 volumio volumio[676]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 26 10:54:53 volumio volumio[676]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 26 10:54:55 volumio volumio[676]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 26 10:54:55 volumio volumio[676]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 26 10:54:55 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:54:55 volumio volumio[676]: info: Starting MyVolumio Remote Streaming Endpoints Oct 26 10:54:55 volumio volumio[676]: info: MyVolumio login type: Token Oct 26 10:54:55 volumio volumio[676]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 26 10:54:55 volumio volumio[676]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 26 10:54:58 volumio volumio[676]: info: Starting Streaming Service Transparent Proxy Oct 26 10:54:58 volumio volumio[676]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 26 10:54:58 volumio volumio[676]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 26 10:54:58 volumio volumio[676]: info: Streaming services startup Oct 26 10:54:58 volumio volumio[676]: info: Starting Streaming Daemon Oct 26 10:54:58 volumio sudo[1150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 10:54:58 volumio sudo[1150]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:54:58 volumio volumio[676]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 26 10:54:58 volumio sudo[1150]: pam_unix(sudo:session): session closed for user root Oct 26 10:54:58 volumio volumio[676]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 26 10:54:58 volumio volumio[676]: error: Cannot start Volumio Streaming Daemon Oct 26 10:54:58 volumio volumio[676]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 10:54:58 volumio volumio[676]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 10:54:59 volumio volumio[676]: error: MyVolumio Custom Token format not valid, refreshing it Oct 26 10:55:01 volumio volumio[676]: STREAMING PROXY: Starting server on port 3245 Oct 26 10:55:01 volumio volumio[676]: Node JS runtime: 14 Oct 26 10:55:02 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 10:55:02 volumio volumio[676]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 26 10:55:02 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 26 10:55:02 volumio volumio[676]: info: Received Get System Version Oct 26 10:55:02 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:55:02 volumio volumio[1069]: ................................................................++++ Oct 26 10:55:02 volumio volumio[676]: info: Received Get System Info Oct 26 10:55:02 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 10:55:02 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 10:55:02 volumio volumio[676]: info: Discovery: Getting this device information Oct 26 10:55:02 volumio volumio[1069]: e is 65537 (0x010001) Oct 26 10:55:02 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:55:02 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:02 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 10:55:02 volumio volumio[1069]: writing RSA key Oct 26 10:55:04 volumio volumio[676]: info: MyVolumio login type: Token Oct 26 10:55:07 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:55:07 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:07 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 10:55:08 volumio volumio[676]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 26 10:55:08 volumio volumio-remote-updater[491]: No test mode Oct 26 10:55:08 volumio volumio-remote-updater[491]: No alpha test mode Oct 26 10:55:08 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 26 10:55:10 volumio volumio[676]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 26 10:55:10 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 26 10:55:10 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 10:55:11 volumio go-librespot[1038]: time="2025-10-26T10:55:11Z" level=trace msg="sent dealer ping" Oct 26 10:55:11 volumio go-librespot[1038]: time="2025-10-26T10:55:11Z" level=trace msg="received dealer pong" Oct 26 10:55:12 volumio volumio[676]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 26 10:55:14 volumio volumio[676]: info: MyVolumio token set successfully Oct 26 10:55:14 volumio volumio[676]: info: MYVOLUMIO: Adding device Oct 26 10:55:14 volumio volumio[676]: info: MYVOLUMIO: Evaluating Server Oct 26 10:55:16 volumio volumio[676]: info: MyVolumio status changed Oct 26 10:55:16 volumio volumio[676]: info: Streaming services startup Oct 26 10:55:16 volumio volumio[676]: info: Starting Streaming Daemon Oct 26 10:55:16 volumio volumio[676]: info: Removing browser output: myVolumio user plan is not superstar Oct 26 10:55:16 volumio volumio[676]: info: Removing audio output: Oct 26 10:55:16 volumio volumio[676]: info: Stoppping Tunnel 1 Oct 26 10:55:16 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:16 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:16 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 26 10:55:16 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 26 10:55:16 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 26 10:55:16 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 26 10:55:16 volumio volumio[676]: info: CoreCommandRouter::volumioGetBrowseSources Oct 26 10:55:16 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:55:16 volumio sudo[1248]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 10:55:16 volumio sudo[1250]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 26 10:55:16 volumio sudo[1248]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:16 volumio sudo[1250]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:16 volumio sudo[1248]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:16 volumio sudo[1250]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:17 volumio ntpd[633]: Soliciting pool server 172.232.63.219 Oct 26 10:55:17 volumio volumio[676]: info: CoreCommandRouter::volumioGetState Oct 26 10:55:17 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:17 volumio volumio[676]: info: Setting Geolocation for MyVolumio to eu4 Oct 26 10:55:17 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:17 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:17 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:17 volumio volumio[676]: info: Remote SSH Stopped Oct 26 10:55:17 volumio volumio[676]: error: Cannot start Volumio Streaming Daemon Oct 26 10:55:18 volumio volumio[676]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 10:55:18 volumio volumio[676]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 10:55:18 volumio ntpd[633]: Soliciting pool server 188.165.49.6 Oct 26 10:55:18 volumio ntpd[633]: Soliciting pool server 185.123.84.51 Oct 26 10:55:18 volumio volumio[676]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 26 10:55:18 volumio volumio[676]: info: Completed starting MyVolumio Plugin Oct 26 10:55:18 volumio volumio[676]: [Metrics] CommandRouter: 58s 807.77ms Oct 26 10:55:18 volumio volumio[676]: info: CoreCommandRouter::volumiosetStartupVolume Oct 26 10:55:18 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:18 volumio volumio[676]: info: VolumeController:: Setting startup Volume 40 Oct 26 10:55:18 volumio volumio[676]: info: VolumeController::SetAlsaVolume40 Oct 26 10:55:18 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:18 volumio volumio[676]: info: CoreCommandRouter::Close All Modals sent Oct 26 10:55:18 volumio volumio[676]: info: CoreCommandRouter::Close All Modals sent Oct 26 10:55:18 volumio volumio[676]: info: CoreStateMachine::pushState Oct 26 10:55:18 volumio volumio[676]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:18 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:55:18 volumio volumio[676]: info: CoreCommandRouter::volumioPushState Oct 26 10:55:19 volumio ntpd[633]: Soliciting pool server 45.90.162.253 Oct 26 10:55:19 volumio ntpd[633]: Soliciting pool server 79.143.250.33 Oct 26 10:55:19 volumio volumio[676]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Oct 26 10:55:19 volumio volumio[676]: SPOTIFY: SPOTIFY VOLUME 100 Oct 26 10:55:19 volumio volumio[676]: SPOTIFY: VOLUMIO VOLUME 40 Oct 26 10:55:19 volumio volumio[676]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 26 10:55:19 volumio volumio[676]: info: Setting Spotify Volume from Volumio: 40 Oct 26 10:55:19 volumio volumio[676]: info: Updating MyVolumio device info Oct 26 10:55:19 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:19 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:19 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:20 volumio ntpd[633]: Soliciting pool server 38.143.19.16 Oct 26 10:55:20 volumio ntpd[633]: Soliciting pool server 5.196.76.84 Oct 26 10:55:20 volumio ntpd[633]: Soliciting pool server 176.137.36.37 Oct 26 10:55:20 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 26 10:55:20 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 26 10:55:20 volumio volumio[676]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 26 10:55:21 volumio ntpd[633]: Soliciting pool server 109.190.177.205 Oct 26 10:55:21 volumio ntpd[633]: Soliciting pool server 62.210.217.202 Oct 26 10:55:21 volumio ntpd[633]: Soliciting pool server 193.52.136.2 Oct 26 10:55:21 volumio volumio[676]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 26 10:55:21 volumio volumio[676]: SPOTIFY: SETTING SPOTIFY VOLUME 40 Oct 26 10:55:21 volumio volumio[676]: info: Sending Spotify command with payload to local API: /player/volume Oct 26 10:55:22 volumio ntpd[633]: Soliciting pool server 162.159.200.123 Oct 26 10:55:22 volumio ntpd[633]: Soliciting pool server 5.39.80.51 Oct 26 10:55:22 volumio go-librespot[1038]: time="2025-10-26T10:55:22Z" level=debug msg="update volume requested to 26214/65535" Oct 26 10:55:22 volumio go-librespot[1038]: time="2025-10-26T10:55:22Z" level=debug msg="put connect state because VOLUME_CHANGED" Oct 26 10:55:22 volumio go-librespot[1038]: time="2025-10-26T10:55:22Z" level=trace msg="emitting websocket event: volume" Oct 26 10:55:23 volumio ntpd[633]: Soliciting pool server 51.210.104.72 Oct 26 10:55:23 volumio ntpd[633]: Soliciting pool server 5.42.158.119 Oct 26 10:55:23 volumio volumio[676]: SPOTIFY: received: {"type":"volume","data":{"value":40,"max":100}} Oct 26 10:55:23 volumio volumio[676]: SPOTIFY: RECEIVED SPOTIFY VOLUME 40 Oct 26 10:55:23 volumio volumio[676]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 10:55:24 volumio ntpd[633]: Soliciting pool server 2a02:2178:1000:201::10 Oct 26 10:55:25 volumio ntpd[633]: receive: Unexpected origin timestamp 0xeca87c9c.0517db4b does not match aorg 0000000000.00000000 from server@45.90.162.253 xmt 0xeca87c9d.10e649b4 Oct 26 10:55:25 volumio ntpd[633]: receive: Unexpected origin timestamp 0xeca87c9c.05131797 does not match aorg 0000000000.00000000 from server@5.196.76.84 xmt 0xeca87c9d.114d320a Oct 26 10:55:25 volumio ntpd[633]: receive: Unexpected origin timestamp 0xeca87c9c.050360e7 does not match aorg 0000000000.00000000 from server@193.52.136.2 xmt 0xeca87c9d.1255013a Oct 26 10:55:26 volumio volumio[676]: info: MYVOLUMIO: Adding device Oct 26 10:55:26 volumio volumio[676]: info: MYVOLUMIO: Evaluating Server Oct 26 10:55:27 volumio volumio[676]: info: BOOT COMPLETED Oct 26 10:55:30 volumio volumio[676]: <--- Last few GCs ---> Oct 26 10:55:30 volumio volumio[676]: [676:0x3e5c780] 74682 ms: Scavenge 165.3 (175.6) -> 165.3 (175.6) MB, 4.7 / 0.0 ms (average mu = 0.929, current mu = 0.940) allocation failure Oct 26 10:55:30 volumio volumio[676]: [676:0x3e5c780] 74980 ms: Scavenge (reduce) 188.2 (198.2) -> 188.0 (198.2) MB, 6.7 / 0.0 ms (average mu = 0.929, current mu = 0.940) allocation failure Oct 26 10:55:30 volumio volumio[676]: <--- JS stacktrace ---> Oct 26 10:55:30 volumio volumio[676]: FATAL ERROR: MarkCompactCollector: young object promotion failed Allocation failed - JavaScript heap out of memory Oct 26 10:55:30 volumio go-librespot[1038]: time="2025-10-26T10:55:30Z" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Oct 26 10:55:30 volumio volumio-remote-updater[491]: [2025-10-26 10:55:30] [info] asio async_read_at_least error: system:104 (Connection reset by peer) Oct 26 10:55:30 volumio volumio-remote-updater[491]: [2025-10-26 10:55:30] [error] handle_read_frame error: websocketpp.transport:2 (Underlying Transport Error) Oct 26 10:55:30 volumio volumio-remote-updater[491]: [2025-10-26 10:55:30] [disconnect] Disconnect close local:[1006,Underlying Transport Error] remote:[1006] Oct 26 10:55:30 volumio systemd[1]: volumio.service: Main process exited, code=killed, status=11/SEGV Oct 26 10:55:30 volumio systemd[1]: volumio.service: Failed with result 'signal'. Oct 26 10:55:30 volumio systemd[1]: Started dynamicswap service. Oct 26 10:55:30 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 26 10:55:30 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Oct 26 10:55:30 volumio systemd[1]: Stopped Volumio Backend Module. Oct 26 10:55:30 volumio systemd[1]: Started Volumio Backend Module. Oct 26 10:55:30 volumio systemd[1]: dynamicswap.service: Succeeded. Oct 26 10:55:33 volumio volumio[1308]: info: ------------------------------------------- Oct 26 10:55:33 volumio volumio[1308]: info: ----- Volumio3 ---- Oct 26 10:55:33 volumio volumio[1308]: info: ------------------------------------------- Oct 26 10:55:33 volumio volumio[1308]: info: ----- System startup ---- Oct 26 10:55:33 volumio volumio[1308]: info: ------------------------------------------- Oct 26 10:55:35 volumio volumio[1308]: info: MYVOLUMIO Environment detected Oct 26 10:55:35 volumio volumio-remote-updater[491]: [2025-10-26 10:55:35] [connect] Successful connection Oct 26 10:55:35 volumio volumio[1308]: info: Plugin folders cleanup Oct 26 10:55:35 volumio volumio[1308]: info: Scanning into folder /volumio/app/plugins/ Oct 26 10:55:35 volumio volumio[1308]: info: Scanning category audio_interface Oct 26 10:55:35 volumio volumio[1308]: info: Scanning category miscellanea Oct 26 10:55:35 volumio volumio[1308]: info: Scanning category music_service Oct 26 10:55:35 volumio volumio[1308]: info: Scanning category plugins.json Oct 26 10:55:35 volumio volumio[1308]: info: Scanning category system_controller Oct 26 10:55:35 volumio volumio[1308]: info: Scanning category user_interface Oct 26 10:55:35 volumio volumio[1308]: info: Scanning into folder /data/plugins/ Oct 26 10:55:35 volumio volumio[1308]: info: Scanning category music_service Oct 26 10:55:35 volumio volumio[1308]: info: Plugin folders cleanup completed Oct 26 10:55:35 volumio volumio[1308]: info: ------------------------------------------- Oct 26 10:55:35 volumio volumio[1308]: info: ----- Core plugins startup ---- Oct 26 10:55:35 volumio volumio[1308]: info: ------------------------------------------- Oct 26 10:55:35 volumio volumio[1308]: info: Loading plugins from folder /volumio/app/plugins/ Oct 26 10:55:35 volumio volumio[1308]: info: Adding plugin upnp to MyMusic Plugins Oct 26 10:55:35 volumio volumio[1308]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 26 10:55:35 volumio volumio[1308]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 26 10:55:35 volumio volumio[1308]: info: Loading plugins from folder /data/plugins/ Oct 26 10:55:35 volumio volumio[1308]: info: Loading plugin "system"... Oct 26 10:55:35 volumio volumio[1308]: info: Loading plugin "appearance"... Oct 26 10:55:37 volumio volumio[1308]: info: Loading plugin "network"... Oct 26 10:55:37 volumio volumio[1308]: info: Refreshing Cached IP Addresses Oct 26 10:55:37 volumio sudo[1329]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 10:55:37 volumio sudo[1329]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:37 volumio sudo[1331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 10:55:37 volumio sudo[1329]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:37 volumio sudo[1331]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:37 volumio volumio[1308]: info: Loading plugin "services"... Oct 26 10:55:37 volumio volumio[1308]: info: Loading plugin "alsa_controller"... Oct 26 10:55:37 volumio sudo[1340]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 26 10:55:37 volumio sudo[1340]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:37 volumio sudo[1331]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:37 volumio sudo[1340]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:38 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:55:38 volumio volumio[1308]: info: Loading plugin "wizard"... Oct 26 10:55:38 volumio volumio[1308]: info: Loading plugin "networkfs"... Oct 26 10:55:38 volumio volumio[1308]: info: Cannot mount NAS DS1520 at system boot, trial number 1 ,retrying in 5 seconds Oct 26 10:55:38 volumio volumio[1308]: info: Starting Udev Watcher for removable devices Oct 26 10:55:38 volumio volumio[1308]: info: Ignoring mount for partition: boot Oct 26 10:55:38 volumio volumio[1308]: info: Ignoring mount for partition: volumio Oct 26 10:55:38 volumio volumio[1308]: info: Ignoring mount for partition: volumio_data Oct 26 10:55:38 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 10:55:38 volumio volumio[1308]: info: Loading plugin "volumio_command_line_client"... Oct 26 10:55:38 volumio volumio[1308]: info: Loading plugin "upnp"... Oct 26 10:55:38 volumio volumio[1308]: info: [1761476138217] Starting Upmpd Daemon Oct 26 10:55:38 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 10:55:38 volumio volumio[1308]: info: Loading plugin "my_music"... Oct 26 10:55:38 volumio volumio[1308]: info: Loading plugin "mpd"... Oct 26 10:55:38 volumio volumio[1308]: info: Loading plugin "upnp_browser"... Oct 26 10:55:39 volumio volumio[1308]: info: Loading plugin "alarm-clock"... Oct 26 10:55:39 volumio volumio[1308]: info: Loading plugin "airplay_emulation"... Oct 26 10:55:39 volumio volumio[1308]: info: Starting Shairport Sync Oct 26 10:55:39 volumio volumio[1308]: info: Loading plugin "last_100"... Oct 26 10:55:39 volumio volumio[1308]: info: Loading plugin "webradio"... Oct 26 10:55:39 volumio volumio[1308]: info: Loading plugin "i2s_dacs"... Oct 26 10:55:40 volumio volumio[1308]: info: Loading plugin "volumiodiscovery"... Oct 26 10:55:40 volumio volumio[1308]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 10:55:40 volumio volumio[1308]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 10:55:40 volumio volumio[1308]: *** WARNING *** For more information see Oct 26 10:55:40 volumio node[1308]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 10:55:40 volumio volumio[1308]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 10:55:40 volumio volumio[1308]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 10:55:40 volumio volumio[1308]: *** WARNING *** For more information see Oct 26 10:55:40 volumio node[1308]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 10:55:40 volumio node[1308]: *** WARNING *** For more information see Oct 26 10:55:40 volumio node[1308]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 10:55:40 volumio node[1308]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 10:55:40 volumio node[1308]: *** WARNING *** For more information see Oct 26 10:55:40 volumio volumio[1308]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 26 10:55:40 volumio volumio[1308]: info: Discovery: Started advertising with name: Volumio Oct 26 10:55:40 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 10:55:40 volumio volumio[1308]: info: Loading plugin "spop"... Oct 26 10:55:42 volumio go-librespot[1038]: time="2025-10-26T10:55:42Z" level=trace msg="sent dealer ping" Oct 26 10:55:42 volumio go-librespot[1038]: time="2025-10-26T10:55:42Z" level=trace msg="received dealer pong" Oct 26 10:55:42 volumio volumio[1308]: info: Loading plugin "outputs"... Oct 26 10:55:42 volumio volumio[1308]: info: Loading plugin "albumart"... Oct 26 10:55:42 volumio volumio[1308]: info: Plugin example_plugin is not enabled Oct 26 10:55:42 volumio volumio[1308]: info: Loading plugin "inputs"... Oct 26 10:55:42 volumio volumio[1308]: info: Loading plugin "updater_comm"... Oct 26 10:55:42 volumio volumio[1308]: info: Plugin mpdemulation is not enabled Oct 26 10:55:42 volumio volumio[1308]: info: Loading plugin "rest_api"... Oct 26 10:55:42 volumio volumio[1308]: info: Loading plugin "websocket"... Oct 26 10:55:42 volumio volumio[1308]: info: Starting Socket.io Server version 2.3.0 Oct 26 10:55:42 volumio volumio[1308]: info: Plugin minidlna is not enabled Oct 26 10:55:42 volumio volumio[1308]: info: Loading i18n strings for locale fr Oct 26 10:55:42 volumio volumio[1308]: Updating browse sources language Oct 26 10:55:42 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::initPlayerControls Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 10:55:43 volumio volumio[1308]: Forking 3 albumart workers Oct 26 10:55:43 volumio volumio[1308]: Express server listening on port 3000 Oct 26 10:55:43 volumio volumio[1308]: [Metrics] WebUI: 10s 449.50ms Oct 26 10:55:43 volumio volumio[1308]: info: CoreStateMachine::resetVolumioState Oct 26 10:55:43 volumio volumio[1308]: info: CoreStateMachine::getcurrentVolume Oct 26 10:55:43 volumio volumio[1308]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 10:55:43 volumio volumio[1308]: info: Cannot mount NAS DS1520 at system boot, trial number 2 ,retrying in 5 seconds Oct 26 10:55:43 volumio volumio[1308]: info: Volumio Network Manager: Network status updated: 1 Oct 26 10:55:43 volumio volumio[1308]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Oct 26 10:55:43 volumio volumio[1308]: wlan0 Interface doesn't support scanning. Oct 26 10:55:43 volumio volumio[1308]: info: Cannot use regular scanning, forcing with ap-force Oct 26 10:55:43 volumio sudo[1395]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Oct 26 10:55:43 volumio sudo[1395]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:43 volumio sudo[1395]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:43 volumio volumio[1308]: command failed: No such device (-19) Oct 26 10:55:43 volumio volumio[1308]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Oct 26 10:55:43 volumio volumio[1308]: command failed: No such device (-19) Oct 26 10:55:43 volumio volumio[1308]: verbose: New Socket.io Connection to 192.168.0.51 from 192.168.0.33 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Oct 26 10:55:43 volumio volumio[1308]: verbose: New Socket.io Connection to 192.168.0.51 from 192.168.0.33 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Oct 26 10:55:43 volumio volumio[1308]: Unable to parse: Oct 26 10:55:43 volumio volumio[1308]: Simple mixer control 'Master',0 Oct 26 10:55:43 volumio volumio[1308]: Capabilities: volume volume-joined Oct 26 10:55:43 volumio volumio[1308]: Playback channels: Mono Oct 26 10:55:43 volumio volumio[1308]: Capture channels: Mono Oct 26 10:55:43 volumio volumio[1308]: Limits: 0 - 248 Oct 26 10:55:43 volumio volumio[1308]: Mono: 100 [40%] Oct 26 10:55:43 volumio volumio[1308]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:44 volumio volumio[1308]: info: Reloading queue from file Oct 26 10:55:44 volumio volumio[1308]: info: CoreStateMachine::setRepeat false single undefined Oct 26 10:55:44 volumio volumio[1308]: info: CoreStateMachine::pushState Oct 26 10:55:44 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::volumioPushState Oct 26 10:55:44 volumio volumio[1308]: info: CoreStateMachine::setRandom true Oct 26 10:55:44 volumio volumio[1308]: info: CoreStateMachine::pushState Oct 26 10:55:44 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::volumioPushState Oct 26 10:55:44 volumio volumio[1308]: info: Setting Device type: Raspberry PI Oct 26 10:55:44 volumio volumio[1308]: info: Completed loading Core Plugins Oct 26 10:55:44 volumio volumio[1308]: info: Preparing to generate the ALSA configuration file Oct 26 10:55:44 volumio volumio[1308]: Unable to parse: Oct 26 10:55:44 volumio volumio[1308]: Simple mixer control 'Master',0 Oct 26 10:55:44 volumio volumio[1308]: Capabilities: volume volume-joined Oct 26 10:55:44 volumio volumio[1308]: Playback channels: Mono Oct 26 10:55:44 volumio volumio[1308]: Capture channels: Mono Oct 26 10:55:44 volumio volumio[1308]: Limits: 0 - 248 Oct 26 10:55:44 volumio volumio[1308]: Mono: 100 [40%] Oct 26 10:55:44 volumio volumio[1308]: info: VolumeController:: Volume=undefined Mute =false Oct 26 10:55:44 volumio volumio[1308]: info: CoreStateMachine::pushState Oct 26 10:55:44 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::volumioPushState Oct 26 10:55:44 volumio volumio[1308]: info: CoreStateMachine::updateTrackBlock Oct 26 10:55:44 volumio volumio[1308]: info: CorePlayQueue::getTrackBlock Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 10:55:44 volumio volumio[1308]: info: Asound.conf file unchanged, so no further update is needed Oct 26 10:55:44 volumio volumio[1308]: info: Output device has changed, restarting MPD Oct 26 10:55:44 volumio volumio[1308]: info: Output device has changed, restarting Shairport Sync Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:44 volumio sudo[1407]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 10:55:44 volumio sudo[1407]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:44 volumio sudo[1407]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:44 volumio sudo[1409]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 10:55:44 volumio sudo[1409]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:44 volumio volumio[1308]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 10:55:44 volumio volumio[1308]: info: ___________ START PLUGINS ___________ Oct 26 10:55:44 volumio systemd[1]: Stopping Music Player Daemon... Oct 26 10:55:44 volumio volumio[1308]: info: ControllerMpd::onStart: Initializing MPD Oct 26 10:55:44 volumio volumio[1308]: info: Creating MPD Configuration file Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 10:55:44 volumio volumio[1308]: info: [1761476144761] CoreMusicLibrary::Adding element Serveurs Média Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:55:44 volumio sudo[1416]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 10:55:44 volumio sudo[1416]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:44 volumio sudo[1418]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 10:55:44 volumio sudo[1418]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:44 volumio sudo[1416]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:44 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:45 volumio volumio[1308]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:45 volumio volumio[1308]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 10:55:45 volumio volumio[1308]: info: [1761476145119] CoreMusicLibrary::Adding element Last_100 Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 10:55:45 volumio volumio[1308]: info: [1761476145131] CoreMusicLibrary::Adding element Webradio Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:55:45 volumio volumio[1308]: info: Initializing BBC Radios Oct 26 10:55:45 volumio systemd[1]: mpd.service: Succeeded. Oct 26 10:55:45 volumio systemd[1]: Stopped Music Player Daemon. Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:45 volumio systemd[1]: Starting Music Player Daemon... Oct 26 10:55:45 volumio volumio[1308]: info: Creating Spotify config file Oct 26 10:55:45 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:45 volumio sudo[1429]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 10:55:45 volumio sudo[1429]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:45 volumio sudo[1429]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:45 volumio volumio[1308]: info: Volumio Calling Home Oct 26 10:55:45 volumio volumio[1308]: Starting albumart workers Oct 26 10:55:45 volumio volumio[1308]: Starting albumart workers Oct 26 10:55:46 volumio volumio[1308]: Starting albumart workers Oct 26 10:55:46 volumio volumio[1308]: info: Discovery: adding 29c73bf8-e642-46f5-8a40-11aaf85d9de1 Oct 26 10:55:46 volumio volumio[1308]: info: Discovery: Found device Volumio Oct 26 10:55:46 volumio volumio[1308]: info: CoreCommandRouter::volumioGetState Oct 26 10:55:46 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:46 volumio volumio[1308]: info: MPD Permissions set Oct 26 10:55:46 volumio volumio[1308]: info: MPD Permissions set Oct 26 10:55:46 volumio volumio[1308]: Unable to parse: Oct 26 10:55:46 volumio volumio[1308]: Simple mixer control 'Master',0 Oct 26 10:55:46 volumio volumio[1308]: Capabilities: volume volume-joined Oct 26 10:55:46 volumio volumio[1308]: Playback channels: Mono Oct 26 10:55:46 volumio volumio[1308]: Capture channels: Mono Oct 26 10:55:46 volumio volumio[1308]: Limits: 0 - 248 Oct 26 10:55:46 volumio volumio[1308]: Mono: 100 [40%] Oct 26 10:55:46 volumio volumio[1308]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Oct 26 10:55:46 volumio volumio[1308]: info: Volumio called home Oct 26 10:55:46 volumio volumio[1308]: info: Spotify config file written Oct 26 10:55:46 volumio sudo[1447]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 26 10:55:46 volumio sudo[1447]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:46 volumio systemd[1]: Stopping go-librespot Daemon... Oct 26 10:55:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 26 10:55:46 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 26 10:55:46 volumio systemd[1]: Stopped go-librespot Daemon. Oct 26 10:55:47 volumio systemd[1]: Started go-librespot Daemon. Oct 26 10:55:47 volumio go-librespot[1449]: go-librespot daemon starting... Oct 26 10:55:47 volumio volumio[1308]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio sudo[1447]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:47 volumio go-librespot[1449]: time="2025-10-26T10:55:47Z" level=info msg="running go-librespot 0.3.2" Oct 26 10:55:47 volumio go-librespot[1449]: time="2025-10-26T10:55:47Z" level=debug msg="app state loaded" Oct 26 10:55:47 volumio go-librespot[1449]: time="2025-10-26T10:55:47Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 10:55:47 volumio volumio[1308]: info: No need to fix Spotify hosts Oct 26 10:55:47 volumio volumio[1308]: Unable to parse: Oct 26 10:55:47 volumio volumio[1308]: Simple mixer control 'Master',0 Oct 26 10:55:47 volumio volumio[1308]: Capabilities: volume volume-joined Oct 26 10:55:47 volumio volumio[1308]: Playback channels: Mono Oct 26 10:55:47 volumio volumio[1308]: Capture channels: Mono Oct 26 10:55:47 volumio volumio[1308]: Limits: 0 - 248 Oct 26 10:55:47 volumio volumio[1308]: Mono: 100 [40%] Oct 26 10:55:47 volumio volumio[1308]: info: VolumeController:: Volume=undefined Mute =false Oct 26 10:55:47 volumio volumio[1308]: info: CoreStateMachine::pushState Oct 26 10:55:47 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:47 volumio volumio-remote-updater[491]: [2025-10-26 10:55:47] [connect] Successful connection Oct 26 10:55:47 volumio volumio[1308]: info: CoreCommandRouter::volumioPushState Oct 26 10:55:47 volumio go-librespot[1449]: time="2025-10-26T10:55:47Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 10:55:47 volumio go-librespot[1449]: time="2025-10-26T10:55:47Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 10:55:47 volumio go-librespot[1449]: time="2025-10-26T10:55:47Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 10:55:47 volumio go-librespot[1449]: time="2025-10-26T10:55:47Z" level=info msg="zeroconf server listening on port 34799" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="obtained new client token: AAD6xLOLV8JXIh/CspYWXE2/IqBJ6JxzLOtS4v41uBRYBhon5GJ0sTExgUKhDxUN7fBs38FiR//fkphH1Flmgul8vWnSH5bxJFabVvP/+h56OBy9ZsDgwf87VZcwCO20IWl9VOFiAO257mMFDmDjFgKP36dC8FUULXP4aGLaFBmi/lpoyOqh0EGRM7ac0Rvg8tOo73L2/8uke7/e6UumYR4StRKuMawyUtWRKdUmKDjohPgKXpp1" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="completed keyexchange" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="completed challenge" Oct 26 10:55:48 volumio volumio[1308]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 10:55:48 volumio volumio[1308]: SPOTIFY: BQBkZocoER05Gx8WprjjVuIdvfMbwQnxjUApIR5IieF8T-2ljtyqJXYk6Ng5vGxXkxT49ONfaheZJFNM66O5tdklzeX0H39owoeMB8PXunUzpNNiTPYmncHTyPC3t3zqY36SSD8RwhB_qT5DjcK8vjH2ogc3Gbeu09PgNq-75gJM4sDHwssXCReZndDRWn2YPSA06ZZ-MOFGpbZuZnpkSkxzATj3Gw1d9_CFtUeCVay3Wd3PnHMsPzbpTXc4D46JdqDy52yQfqUiOlhOMwI5Fp_PCHc Oct 26 10:55:48 volumio volumio[1308]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 10:55:48 volumio volumio[1308]: info: New Spotify access token = BQBkZocoER05Gx8WprjjVuIdvfMbwQnxjUApIR5IieF8T-2ljtyqJXYk6Ng5vGxXkxT49ONfaheZJFNM66O5tdklzeX0H39owoeMB8PXunUzpNNiTPYmncHTyPC3t3zqY36SSD8RwhB_qT5DjcK8vjH2ogc3Gbeu09PgNq-75gJM4sDHwssXCReZndDRWn2YPSA06ZZ-MOFGpbZuZnpkSkxzATj3Gw1d9_CFtUeCVay3Wd3PnHMsPzbpTXc4D46JdqDy52yQfqUiOlhOMwI5Fp_PCHc Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=info msg="authenticated AP" username="al***ue" Oct 26 10:55:48 volumio volumio[1308]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 26 10:55:48 volumio volumio-remote-updater[491]: [2025-10-26 10:55:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1761476147 101 Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=info msg="authenticated Login5" username="al***ue" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="initializing zeroconf session" username="al***ue" Oct 26 10:55:48 volumio volumio[1308]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 4 Oct 26 10:55:48 volumio sudo[1489]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="dealer connection opened" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=trace msg="starting accesspoint recv loop" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=trace msg="starting dealer recv loop" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=trace msg="received accesspoint ping" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 26 10:55:48 volumio sudo[1489]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="received connection id: ZGIwYzE3YTAtNjRi...QjFDMzc2NUQ1Rg==" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=trace msg="received accesspoint pong ack" Oct 26 10:55:48 volumio sudo[1489]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:48 volumio volumio[1308]: info: Starting Shairport Sync Oct 26 10:55:48 volumio sudo[1492]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 10:55:48 volumio sudo[1492]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:48 volumio volumio[1308]: info: Starting Shairport Sync Oct 26 10:55:48 volumio sudo[1494]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 10:55:48 volumio sudo[1494]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:48 volumio sudo[1492]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:48 volumio volumio[1308]: info: Starting Shairport Sync Oct 26 10:55:48 volumio go-librespot[1449]: time="2025-10-26T10:55:48Z" level=debug msg="put connect state because NEW_DEVICE" Oct 26 10:55:48 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 10:55:48 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 26 10:55:48 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 10:55:48 volumio volumio[1308]: info: CoreCommandRouter::volumioGetState Oct 26 10:55:48 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 10:55:48 volumio sudo[1494]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:48 volumio sudo[1515]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 10:55:48 volumio sudo[1515]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:48 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:48 volumio sudo[1504]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 10:55:48 volumio sudo[1504]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:48 volumio volumio[1308]: info: Cannot mount NAS DS1520 at system boot, trial number 3 ,retrying in 5 seconds Oct 26 10:55:49 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 10:55:49 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 26 10:55:49 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 10:55:49 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 10:55:49 volumio sudo[1504]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:49 volumio sudo[1515]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:49 volumio volumio[1308]: info: Shairport-Sync Started Oct 26 10:55:49 volumio volumio[1308]: Error adding Membership: Error: addMembership EINVAL Oct 26 10:55:49 volumio volumio[1308]: info: Shairport-Sync Started Oct 26 10:55:49 volumio volumio[1308]: info: Shairport-Sync Started Oct 26 10:55:49 volumio sudo[1527]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 26 10:55:49 volumio sudo[1527]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 10:55:49 volumio volumio[1308]: SPOTIFY: User informations: {"country":"FR","display_name":"alfique","email":"alfique@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/alfique"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/alfique","id":"alfique","images":[],"product":"premium","type":"user","uri":"spotify:user:alfique"} Oct 26 10:55:49 volumio volumio[1308]: info: Spotify Successfully logged in Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 10:55:49 volumio volumio[1308]: info: [1761476149447] CoreMusicLibrary::Adding element Spotify Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:55:49 volumio sudo[1527]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:49 volumio volumio[1308]: Cannot find translation for source Spotify Oct 26 10:55:49 volumio volumio[1308]: info: Upmpdcli Daemon Started Oct 26 10:55:49 volumio mpd[1439]: Oct 26 10:55 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 26 10:55:49 volumio volumio[1308]: verbose: New Socket.io Connection to 192.168.0.51 from 192.168.0.33 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::volumioGetVisibleSources Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::volumioGetState Oct 26 10:55:49 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 26 10:55:49 volumio volumio[1308]: info: Received Get System Info Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 10:55:49 volumio volumio[1308]: info: Discovery: Getting this device information Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::volumioGetState Oct 26 10:55:49 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 10:55:49 volumio volumio[1308]: info: CoreCommandRouter::volumioGetState Oct 26 10:55:49 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:49 volumio volumio[1308]: info: Listing playlists Oct 26 10:55:50 volumio volumio[1308]: info: VolumeController::SetAlsaVolume0 Oct 26 10:55:50 volumio volumio[1308]: info: CoreStateMachine::pushState Oct 26 10:55:50 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:50 volumio volumio[1308]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 10:55:50 volumio volumio[1308]: info: CoreCommandRouter::volumioPushState Oct 26 10:55:51 volumio volumio[1308]: info: go-librespot daemon successfully initialized Oct 26 10:55:53 volumio systemd[1]: Started Music Player Daemon. Oct 26 10:55:53 volumio sudo[1418]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:53 volumio sudo[1409]: pam_unix(sudo:session): session closed for user root Oct 26 10:55:53 volumio volumio[1308]: info: Completed starting Core Plugins Oct 26 10:55:53 volumio volumio[1308]: info: ------------------------------------------- Oct 26 10:55:53 volumio volumio[1308]: info: ----- MyVolumio plugins startup ---- Oct 26 10:55:53 volumio volumio[1308]: info: ------------------------------------------- Oct 26 10:55:53 volumio volumio[1308]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 26 10:55:53 volumio volumio[1308]: error: MPD error: The expression evaluated to a falsy value: Oct 26 10:55:53 volumio volumio[1308]: assert.ok(self.idling) Oct 26 10:55:53 volumio volumio[1308]: error: The expression evaluated to a falsy value: Oct 26 10:55:53 volumio volumio[1308]: assert.ok(self.idling) Oct 26 10:55:53 volumio volumio[1308]: info: MPD running with PID1439 Oct 26 10:55:53 volumio volumio[1308]: ,establishing connection Oct 26 10:55:53 volumio volumio[1308]: error: updateQueue error: null Oct 26 10:55:53 volumio volumio[1308]: error: updateQueue error: null Oct 26 10:55:53 volumio volumio[1308]: info: Cannot mount NAS DS1520 at system boot, trial number 4 ,retrying in 5 seconds Oct 26 10:55:54 volumio volumio[1308]: info: Initializing connection to go-librespot Websocket Oct 26 10:55:54 volumio go-librespot[1449]: time="2025-10-26T10:55:54Z" level=debug msg="new websocket client" Oct 26 10:55:54 volumio volumio[1308]: info: Connection to go-librespot Websocket established Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="handling transfer player command from 79806ef57b2f2194cd45c6f0a7f5df2681e92b02" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="resolved context of track" uri="spotify:album:1iyLkKp8f8XZjOxDD2PEo9" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=trace msg="fetched new page 0 with 20 items (list: 20)" uri="spotify:album:1iyLkKp8f8XZjOxDD2PEo9" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="loading track (paused: true, position: 40940ms)" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=trace msg="emitting websocket event: will_play" Oct 26 10:55:56 volumio volumio[1308]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:64ByydKWf67CJfIoPc8uLJ","play_origin":""}} Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 391" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1328" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="selected format OGG_VORBIS_320 (dba6d5cd02cd3bb961db38063284ad2c731ae66a)" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="requested aes key for file dba6d5cd02cd3bb961db38063284ad2c731ae66a, gid: 64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=trace msg="found 2 cdn urls" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1108" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="fetched first chunk of 12, total size is 6038764 bytes" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="fetched chunk 4/11, size: 524288" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=trace msg="seek to 40940ms (diff: 107ms, samples: 1805454, bytes: 1548370)" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=debug msg="created new output device" Oct 26 10:55:56 volumio go-librespot[1449]: time="2025-10-26T10:55:56Z" level=info msg="loaded track \"Main Titles - From \\\"Beetlejuice\\\" Soundtrack\" (paused: true, position: 40940ms, duration: 148426ms, prefetched: false)" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=trace msg="emitting websocket event: metadata" Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=trace msg="emitting websocket event: active" Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=debug msg="sending successful reply for dealer request" Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 26 10:55:57 volumio volumio[1308]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:64ByydKWf67CJfIoPc8uLJ","name":"Main Titles - From \"Beetlejuice\" Soundtrack","artist_names":["Danny Elfman"],"album_name":"Beetlejuice (Original Motion Picture Soundtrack)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b8cdf1840f5838dac9c13258","position":40940,"duration":148426,"release_date":"year:1988 month:1 day:1","track_number":1,"disc_number":1}} Oct 26 10:55:57 volumio volumio[1308]: SPOTIFY: received: {"type":"active","data":null} Oct 26 10:55:57 volumio volumio[1308]: info: Aligning Spotify Volume to Volumio Volume Oct 26 10:55:57 volumio volumio[1308]: info: CoreCommandRouter::volumioGetState Oct 26 10:55:57 volumio volumio[1308]: info: CorePlayQueue::getTrack 0 Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=debug msg="fetched chunk 5/11, size: 524288" uri="spotify:track:64ByydKWf67CJfIoPc8uLJ" Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 10:55:57 volumio go-librespot[1449]: time="2025-10-26T10:55:57Z" level=trace msg="emitting websocket event: paused" Oct 26 10:55:57 volumio volumio[1308]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:64ByydKWf67CJfIoPc8uLJ","play_origin":""}} Oct 26 10:55:57 volumio volumio[1308]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 10:55:57 volumio volumio[1308]: TypeError: Cannot read property 'service' of undefined Oct 26 10:55:57 volumio volumio[1308]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Oct 26 10:55:57 volumio volumio[1308]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Oct 26 10:55:57 volumio volumio[1308]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Oct 26 10:55:57 volumio volumio[1308]: at WebSocket.emit (events.js:315:20) Oct 26 10:55:57 volumio volumio[1308]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 26 10:55:57 volumio volumio[1308]: at Receiver.emit (events.js:315:20) Oct 26 10:55:57 volumio volumio[1308]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 26 10:55:57 volumio volumio[1308]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 26 10:55:57 volumio volumio[1308]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 26 10:55:57 volumio volumio[1308]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 26 10:55:57 volumio volumio[1308]: at writeOrBuffer (internal/streams/writable.js:358:12) Oct 26 10:55:57 volumio volumio[1308]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Oct 26 10:55:57 volumio volumio[1308]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 26 10:55:57 volumio volumio[1308]: at Socket.emit (events.js:315:20) Oct 26 10:55:57 volumio volumio[1308]: at addChunk (internal/streams/readable.js:309:12) Oct 26 10:55:57 volumio volumio[1308]: at readableAddChunk (internal/streams/readable.js:284:9) Oct 26 10:55:57 volumio volumio[1308]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 10:55:58 volumio sudo[1558]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-26 10:54 Oct 26 10:55:58 volumio sudo[1558]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"