-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sat 2025-06-28 15:46:48 CEST. -- Jun 28 15:46:31 volumio3 systemd-timedated[943]: Changed local time to Sat Jun 28 15:46:31 2025 Jun 28 15:46:31 volumio3 sudo[941]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:31 volumio3 volumio-time-update[541]: volumio-time-update-util: System time updated successfully. Jun 28 15:46:31 volumio3 systemd[1]: Started Volumio Time Update Utility. Jun 28 15:46:31 volumio3 systemd[1]: Reached target Multi-User System. Jun 28 15:46:31 volumio3 systemd[1]: Reached target Graphical Interface. Jun 28 15:46:31 volumio3 systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 28 15:46:31 volumio3 systemd[1]: Started Run on boot service by wd. Jun 28 15:46:31 volumio3 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jun 28 15:46:31 volumio3 systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 28 15:46:31 volumio3 systemd[1]: Startup finished in 13.478s (kernel) + 16.046s (userspace) = 29.524s. Jun 28 15:46:31 volumio3 volumio[852]: info: Plugin folders cleanup Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning into folder /volumio/app/plugins/ Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning category audio_interface Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning category miscellanea Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning category music_service Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning category plugins.json Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning category system_controller Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning category user_interface Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning into folder /data/plugins/ Jun 28 15:46:31 volumio3 volumio[852]: info: Scanning category music_service Jun 28 15:46:31 volumio3 volumio[852]: info: Plugin folders cleanup completed Jun 28 15:46:31 volumio3 volumio[852]: info: ------------------------------------------- Jun 28 15:46:31 volumio3 volumio[852]: info: ----- Core plugins startup ---- Jun 28 15:46:31 volumio3 volumio[852]: info: ------------------------------------------- Jun 28 15:46:31 volumio3 volumio[852]: info: Loading plugins from folder /volumio/app/plugins/ Jun 28 15:46:31 volumio3 volumio[852]: info: Adding plugin upnp to MyMusic Plugins Jun 28 15:46:31 volumio3 volumio[852]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 28 15:46:31 volumio3 volumio[852]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 28 15:46:31 volumio3 volumio[852]: info: Loading plugins from folder /data/plugins/ Jun 28 15:46:31 volumio3 volumio[852]: info: Loading plugin "system"... Jun 28 15:46:31 volumio3 volumio[852]: info: Loading plugin "appearance"... Jun 28 15:46:31 volumio3 nmbd[746]: [2025/06/28 15:46:31.576048, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Jun 28 15:46:31 volumio3 nmbd[746]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.99.24 for name WORKGROUP<1d>. Jun 28 15:46:31 volumio3 nmbd[746]: This response was from IP 192.168.99.20, reporting an IP address of 192.168.99.20. Jun 28 15:46:32 volumio3 volumio[852]: info: Loading plugin "network"... Jun 28 15:46:32 volumio3 volumio[852]: info: Refreshing Cached IP Addresses Jun 28 15:46:32 volumio3 sudo[954]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 28 15:46:32 volumio3 sudo[954]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:32 volumio3 sudo[954]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:32 volumio3 sudo[956]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 28 15:46:32 volumio3 sudo[956]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:32 volumio3 sudo[956]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:32 volumio3 volumio[852]: info: Loading plugin "services"... Jun 28 15:46:32 volumio3 volumio[852]: info: Loading plugin "alsa_controller"... Jun 28 15:46:32 volumio3 sudo[966]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 28 15:46:32 volumio3 sudo[966]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:32 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 28 15:46:32 volumio3 volumio[852]: info: Loading plugin "wizard"... Jun 28 15:46:32 volumio3 volumio[852]: info: Loading plugin "networkfs"... Jun 28 15:46:32 volumio3 volumio-remote-updater[532]: [2025-06-28 15:46:32] [connect] Successful connection Jun 28 15:46:32 volumio3 volumio[852]: info: Starting Udev Watcher for removable devices Jun 28 15:46:32 volumio3 sudo[982]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=pi,password=js3gr40,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.99.31/bu/music /mnt/NAS/rpi4-2 Jun 28 15:46:32 volumio3 sudo[982]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:32 volumio3 volumio[852]: info: Ignoring mount for partition: boot Jun 28 15:46:32 volumio3 volumio[852]: info: Ignoring mount for partition: volumio Jun 28 15:46:32 volumio3 volumio[852]: info: Ignoring mount for partition: volumio_data Jun 28 15:46:32 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 28 15:46:32 volumio3 volumio[852]: info: Loading plugin "volumio_command_line_client"... Jun 28 15:46:33 volumio3 volumio[852]: info: Loading plugin "upnp"... Jun 28 15:46:33 volumio3 volumio[852]: info: [1751118393027] Starting Upmpd Daemon Jun 28 15:46:33 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 28 15:46:33 volumio3 volumio[852]: info: Loading plugin "my_music"... Jun 28 15:46:33 volumio3 volumio[852]: info: Loading plugin "mpd"... Jun 28 15:46:33 volumio3 kernel: Key type cifs.spnego registered Jun 28 15:46:33 volumio3 kernel: Key type cifs.idmap registered Jun 28 15:46:33 volumio3 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. Jun 28 15:46:33 volumio3 kernel: CIFS: Attempting to mount //192.168.99.31/bu/music Jun 28 15:46:33 volumio3 kernel: cryptd: max_cpu_qlen set to 1000 Jun 28 15:46:33 volumio3 sudo[982]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:33 volumio3 kernel: CIFS: VFS: cifs_mount failed w/return code = -5 Jun 28 15:46:33 volumio3 volumio[852]: info: Loading plugin "upnp_browser"... Jun 28 15:46:34 volumio3 volumio[852]: info: Loading plugin "alarm-clock"... Jun 28 15:46:34 volumio3 volumio[852]: info: Loading plugin "airplay_emulation"... Jun 28 15:46:34 volumio3 volumio[852]: info: Starting Shairport Sync Jun 28 15:46:34 volumio3 volumio[852]: info: Loading plugin "last_100"... Jun 28 15:46:34 volumio3 volumio[852]: info: Loading plugin "webradio"... Jun 28 15:46:34 volumio3 volumio[852]: info: Loading plugin "i2s_dacs"... Jun 28 15:46:34 volumio3 volumio[852]: info: Loading plugin "volumiodiscovery"... Jun 28 15:46:34 volumio3 volumio[852]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 28 15:46:34 volumio3 volumio[852]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 28 15:46:34 volumio3 volumio[852]: *** WARNING *** For more information see Jun 28 15:46:34 volumio3 node[852]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 28 15:46:34 volumio3 volumio[852]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 28 15:46:34 volumio3 volumio[852]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 28 15:46:34 volumio3 volumio[852]: *** WARNING *** For more information see Jun 28 15:46:34 volumio3 node[852]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 28 15:46:34 volumio3 node[852]: *** WARNING *** For more information see Jun 28 15:46:34 volumio3 node[852]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 28 15:46:34 volumio3 node[852]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 28 15:46:34 volumio3 node[852]: *** WARNING *** For more information see Jun 28 15:46:34 volumio3 volumio[852]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 28 15:46:34 volumio3 volumio[852]: info: Discovery: Started advertising with name: Volumio3 Jun 28 15:46:34 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 28 15:46:34 volumio3 volumio[852]: info: Loading plugin "spop"... Jun 28 15:46:35 volumio3 sudo[966]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:36 volumio3 volumio[852]: info: Loading plugin "outputs"... Jun 28 15:46:36 volumio3 volumio[852]: info: Loading plugin "albumart"... Jun 28 15:46:36 volumio3 volumio[852]: info: Plugin example_plugin is not enabled Jun 28 15:46:36 volumio3 volumio[852]: info: Loading plugin "inputs"... Jun 28 15:46:36 volumio3 volumio[852]: info: Loading plugin "updater_comm"... Jun 28 15:46:36 volumio3 volumio[852]: info: Plugin mpdemulation is not enabled Jun 28 15:46:36 volumio3 volumio[852]: info: Loading plugin "rest_api"... Jun 28 15:46:36 volumio3 volumio[852]: info: Loading plugin "websocket"... Jun 28 15:46:36 volumio3 volumio[852]: info: Starting Socket.io Server version 2.3.0 Jun 28 15:46:36 volumio3 volumio[852]: info: Loading i18n strings for locale en Jun 28 15:46:36 volumio3 volumio[852]: Updating browse sources language Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 28 15:46:36 volumio3 volumio[852]: Forking 3 albumart workers Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::initPlayerControls Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 28 15:46:36 volumio3 volumio[852]: Express server listening on port 3000 Jun 28 15:46:36 volumio3 volumio[852]: [Metrics] WebUI: 8s 18.57ms Jun 28 15:46:36 volumio3 volumio[852]: info: CoreStateMachine::resetVolumioState Jun 28 15:46:36 volumio3 volumio[852]: info: CoreStateMachine::getcurrentVolume Jun 28 15:46:36 volumio3 volumio[852]: info: CoreCommandRouter::volumioRetrievevolume Jun 28 15:46:37 volumio3 volumio[852]: info: Volumio Network Manager: Network status updated: 1 Jun 28 15:46:37 volumio3 volumio[852]: info: Cannot mount NAS rpi4-2 at system boot, trial number 1 ,retrying in 5 seconds Jun 28 15:46:37 volumio3 volumio-remote-updater[532]: [2025-06-28 15:46:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1751118392 101 Jun 28 15:46:37 volumio3 volumio[852]: 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: 1 Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 28 15:46:37 volumio3 volumio[852]: info: Reloading queue from file Jun 28 15:46:37 volumio3 volumio[852]: info: VolumeController:: Volume=78 Mute =false Jun 28 15:46:37 volumio3 volumio[852]: info: CoreStateMachine::pushState Jun 28 15:46:37 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::volumioPushState Jun 28 15:46:37 volumio3 volumio[852]: info: CoreStateMachine::updateTrackBlock Jun 28 15:46:37 volumio3 volumio[852]: info: CorePlayQueue::getTrackBlock Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::volumioRetrievevolume Jun 28 15:46:37 volumio3 volumio[852]: info: Setting Device type: Raspberry PI Jun 28 15:46:37 volumio3 volumio[852]: info: CoreStateMachine::setRepeat false single undefined Jun 28 15:46:37 volumio3 volumio[852]: info: CoreStateMachine::pushState Jun 28 15:46:37 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::volumioPushState Jun 28 15:46:37 volumio3 volumio[852]: info: CoreStateMachine::setRandom false Jun 28 15:46:37 volumio3 volumio[852]: info: CoreStateMachine::pushState Jun 28 15:46:37 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::volumioPushState Jun 28 15:46:37 volumio3 volumio[852]: info: Completed loading Core Plugins Jun 28 15:46:37 volumio3 volumio[852]: info: Preparing to generate the ALSA configuration file Jun 28 15:46:37 volumio3 volumio[852]: Starting albumart workers Jun 28 15:46:37 volumio3 volumio[852]: info: Asound.conf file unchanged, so no further update is needed Jun 28 15:46:37 volumio3 volumio[852]: info: Output device has changed, restarting MPD Jun 28 15:46:37 volumio3 volumio[852]: Starting albumart workers Jun 28 15:46:37 volumio3 volumio[852]: Starting albumart workers Jun 28 15:46:37 volumio3 volumio[852]: info: Output device has changed, restarting Shairport Sync Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 28 15:46:37 volumio3 sudo[1062]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 28 15:46:37 volumio3 sudo[1062]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:37 volumio3 sudo[1064]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 28 15:46:37 volumio3 sudo[1064]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:37 volumio3 sudo[1062]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:37 volumio3 systemd[1]: Stopping Music Player Daemon... Jun 28 15:46:37 volumio3 volumio[852]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 28 15:46:37 volumio3 volumio[852]: info: ___________ START PLUGINS ___________ Jun 28 15:46:37 volumio3 volumio[852]: info: ControllerMpd::onStart: Initializing MPD Jun 28 15:46:37 volumio3 volumio[852]: info: Creating MPD Configuration file Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 28 15:46:37 volumio3 sudo[1071]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 28 15:46:37 volumio3 sudo[1071]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 28 15:46:37 volumio3 volumio[852]: info: [1751118397762] CoreMusicLibrary::Adding element Media Servers Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 28 15:46:37 volumio3 sudo[1071]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:37 volumio3 sudo[1073]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 28 15:46:37 volumio3 sudo[1073]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 28 15:46:37 volumio3 volumio[852]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 28 15:46:37 volumio3 systemd[1]: mpd.service: Succeeded. Jun 28 15:46:37 volumio3 systemd[1]: Stopped Music Player Daemon. Jun 28 15:46:37 volumio3 volumio[852]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 28 15:46:37 volumio3 volumio[852]: info: [1751118397925] CoreMusicLibrary::Adding element Last_100 Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 28 15:46:37 volumio3 volumio[852]: info: [1751118397930] CoreMusicLibrary::Adding element Webradio Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 28 15:46:37 volumio3 systemd[1]: Starting Music Player Daemon... Jun 28 15:46:37 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 28 15:46:37 volumio3 volumio[852]: info: Initializing BBC Radios Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 28 15:46:38 volumio3 sudo[1081]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 28 15:46:38 volumio3 sudo[1081]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:38 volumio3 sudo[1081]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:38 volumio3 volumio[852]: info: Creating Spotify config file Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: Volumio Calling Home Jun 28 15:46:38 volumio3 volumio[852]: info: Discovery: adding d42e7524-9646-4121-adf5-eb9b6d28e6a7 Jun 28 15:46:38 volumio3 volumio[852]: info: Discovery: Found device Volumio3 Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::volumioGetState Jun 28 15:46:38 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:38 volumio3 volumio[852]: info: MPD Permissions set Jun 28 15:46:38 volumio3 volumio[852]: info: MPD Permissions set Jun 28 15:46:38 volumio3 volumio[852]: info: VolumeController:: Volume=78 Mute =false Jun 28 15:46:38 volumio3 volumio[852]: info: CoreStateMachine::pushState Jun 28 15:46:38 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::volumioPushState Jun 28 15:46:38 volumio3 volumio[852]: info: Spotify config file written Jun 28 15:46:38 volumio3 sudo[1105]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 28 15:46:38 volumio3 sudo[1105]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:38 volumio3 volumio[852]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 28 15:46:38 volumio3 volumio[852]: info: Volumio called home Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 systemd[1]: Started go-librespot Daemon. Jun 28 15:46:38 volumio3 go-librespot[1109]: Librespot-go daemon starting... Jun 28 15:46:38 volumio3 sudo[1105]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 28 15:46:38 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 28 15:46:39 volumio3 sudo[1141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 28 15:46:39 volumio3 volumio[852]: info: Starting Shairport Sync Jun 28 15:46:39 volumio3 sudo[1141]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:39 volumio3 sudo[1143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 28 15:46:39 volumio3 sudo[1143]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:39 volumio3 sudo[1141]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:39 volumio3 volumio[852]: info: Starting Shairport Sync Jun 28 15:46:39 volumio3 sudo[1143]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:39 volumio3 volumio[852]: info: Starting Shairport Sync Jun 28 15:46:39 volumio3 sudo[1147]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 28 15:46:39 volumio3 sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:39 volumio3 volumio[852]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 28 15:46:39 volumio3 volumio[852]: SPOTIFY: BQATLClZdeK-RsyvCTL2Jb2Ayawug_h392pYQKuyQed_Oa8Es8RUa637elNMMSj7EyCPNL0H0wr28GzzQ19wuxX_j4wwAlQ4Kfx6N3eQLhOeObBcwCOid2wm9MvGGQp7zqW2XwyQ3OaZPcPiU-2SEmw9YFlyetXHBEJEf_RJx08pwQ8lD1KD8ye8lf5Kdu8YvH5mNsD_Ry5oqi3IczXvRhSZkazRZrmUfC-6LOLXH7cGCmBdupjxYg5CNJjMlF1amTIXXYfWQ22RT4Zx8wBWi7Ku2KxDH-iikawvViXIaSNMvPQ Jun 28 15:46:39 volumio3 volumio[852]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 28 15:46:39 volumio3 sudo[1149]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 28 15:46:39 volumio3 volumio[852]: info: New Spotify access token = BQATLClZdeK-RsyvCTL2Jb2Ayawug_h392pYQKuyQed_Oa8Es8RUa637elNMMSj7EyCPNL0H0wr28GzzQ19wuxX_j4wwAlQ4Kfx6N3eQLhOeObBcwCOid2wm9MvGGQp7zqW2XwyQ3OaZPcPiU-2SEmw9YFlyetXHBEJEf_RJx08pwQ8lD1KD8ye8lf5Kdu8YvH5mNsD_Ry5oqi3IczXvRhSZkazRZrmUfC-6LOLXH7cGCmBdupjxYg5CNJjMlF1amTIXXYfWQ22RT4Zx8wBWi7Ku2KxDH-iikawvViXIaSNMvPQ Jun 28 15:46:39 volumio3 volumio[852]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 28 15:46:39 volumio3 sudo[1149]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:39 volumio3 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 28 15:46:39 volumio3 systemd[1]: shairport-sync.service: Succeeded. Jun 28 15:46:39 volumio3 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 28 15:46:39 volumio3 sudo[1152]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 28 15:46:39 volumio3 sudo[1152]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:39 volumio3 go-librespot[1109]: time="2025-06-28T15:46:39+02:00" level=info msg="generated new device id: a554c79ab2f2147d224764a9c275cdc6ef8e9934" Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::volumioGetState Jun 28 15:46:39 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:39 volumio3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 28 15:46:39 volumio3 go-librespot[1109]: time="2025-06-28T15:46:39+02:00" level=debug msg="stored credentials found for xa60m3puti317444kkwsgrlme" Jun 28 15:46:39 volumio3 sudo[1147]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:39 volumio3 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 28 15:46:39 volumio3 systemd[1]: shairport-sync.service: Succeeded. Jun 28 15:46:39 volumio3 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 28 15:46:39 volumio3 volumio[852]: info: Shairport-Sync Started Jun 28 15:46:39 volumio3 volumio[852]: Error adding Membership: Error: addMembership EINVAL Jun 28 15:46:39 volumio3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 28 15:46:39 volumio3 sudo[1149]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:39 volumio3 sudo[1152]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:39 volumio3 volumio[852]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.2 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_6 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.6 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 3 Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::volumioGetState Jun 28 15:46:39 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:39 volumio3 volumio[852]: info: Shairport-Sync Started Jun 28 15:46:39 volumio3 volumio[852]: info: Shairport-Sync Started Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 28 15:46:39 volumio3 volumio[852]: info: Listing playlists Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 28 15:46:39 volumio3 volumio[852]: SPOTIFY: User informations: {"country":"BE","display_name":"Ward.dewerchin","email":"ward.dewerchin@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/xa60m3puti317444kkwsgrlme"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/xa60m3puti317444kkwsgrlme","id":"xa60m3puti317444kkwsgrlme","images":[],"product":"premium","type":"user","uri":"spotify:user:xa60m3puti317444kkwsgrlme"} Jun 28 15:46:39 volumio3 volumio[852]: info: Spotify Successfully logged in Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 28 15:46:39 volumio3 volumio[852]: info: [1751118399652] CoreMusicLibrary::Adding element Spotify Jun 28 15:46:39 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 28 15:46:39 volumio3 volumio[852]: Cannot find translation for source Spotify Jun 28 15:46:39 volumio3 go-librespot[1109]: time="2025-06-28T15:46:39+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 28 15:46:39 volumio3 go-librespot[1109]: time="2025-06-28T15:46:39+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 28 15:46:39 volumio3 go-librespot[1109]: time="2025-06-28T15:46:39+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 28 15:46:39 volumio3 go-librespot[1109]: time="2025-06-28T15:46:39+02:00" level=debug msg="zeroconf server listening on port 43789" Jun 28 15:46:39 volumio3 go-librespot[1109]: time="2025-06-28T15:46:39+02:00" level=debug msg="obtained new client token: AADo+EFUdPV+KmAHAs3o8hYq+uWKZ43Th5v4ocvS8kA6snxTzkI6aUP3MwaOILV2Z2xTtBkJm+skJvLwzrGkOCrfHUf3Xe2WCZYkgmzceT8wIzwA7XrfV+jLCtNmPogpzHdeOCHQn66iRaY3o0c0M93fJ249VNx4nkibhlqteOWrUgRMnH+rWvIZtPdhNPr9o1U+0LfL6XbLZEJ2tausXZ9UJuWwmmS9O+FBYV3zQSoPrU9CjSYjIs07" Jun 28 15:46:39 volumio3 mpd[1094]: Jun 28 15:46 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 28 15:46:39 volumio3 go-librespot[1109]: time="2025-06-28T15:46:39+02:00" level=debug msg="completed keyexchange" Jun 28 15:46:40 volumio3 systemd[1]: Started Music Player Daemon. Jun 28 15:46:40 volumio3 sudo[1073]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:40 volumio3 sudo[1064]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:40 volumio3 volumio[852]: info: Completed starting Core Plugins Jun 28 15:46:40 volumio3 volumio[852]: info: ------------------------------------------- Jun 28 15:46:40 volumio3 volumio[852]: info: ----- MyVolumio plugins startup ---- Jun 28 15:46:40 volumio3 volumio[852]: info: ------------------------------------------- Jun 28 15:46:40 volumio3 volumio[852]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 28 15:46:40 volumio3 volumio[852]: error: MPD error: The expression evaluated to a falsy value: Jun 28 15:46:40 volumio3 volumio[852]: assert.ok(self.idling) Jun 28 15:46:40 volumio3 volumio[852]: error: The expression evaluated to a falsy value: Jun 28 15:46:40 volumio3 volumio[852]: assert.ok(self.idling) Jun 28 15:46:40 volumio3 volumio[852]: info: MPD running with PID1094 Jun 28 15:46:40 volumio3 volumio[852]: ,establishing connection Jun 28 15:46:40 volumio3 volumio[852]: error: updateQueue error: null Jun 28 15:46:40 volumio3 volumio[852]: error: updateQueue error: null Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="completed challenge" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="authenticated as xa60m3puti317444kkwsgrlme" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="authenticated as xa60m3puti317444kkwsgrlme" Jun 28 15:46:40 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 28 15:46:40 volumio3 volumio[852]: info: Received Get System Info Jun 28 15:46:40 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 28 15:46:40 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 28 15:46:40 volumio3 volumio[852]: info: Discovery: Getting this device information Jun 28 15:46:40 volumio3 volumio[852]: info: CoreCommandRouter::volumioGetState Jun 28 15:46:40 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:40 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="dealer connection opened" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="initializing zeroconf session, username: xa60m3puti317444kkwsgrlme" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="received connection id: MDlkZGZlMzMtZTc2OC00MTUwLTg5ZWMtN2UzYTQ3YmI0NThkK2RlYWxlcit0Y3A6Ly8wYWIxNTA1YS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArN0I4MUUyNEYwOTU2Q0FGNTU2Q0I1MEE1NzA2RkI2MzREMDBDOEYxMkExNTNFNkJBQkM0QUNFMzAyMzlGREFGMw==" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="put connect state because NEW_DEVICE" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 28 15:46:40 volumio3 go-librespot[1109]: time="2025-06-28T15:46:40+02:00" level=debug msg="autoplay enabled: false" Jun 28 15:46:41 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Jun 28 15:46:41 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 28 15:46:41 volumio3 volumio[852]: info: Received Get System Info Jun 28 15:46:41 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 28 15:46:41 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 28 15:46:41 volumio3 volumio[852]: info: Discovery: Getting this device information Jun 28 15:46:41 volumio3 volumio[852]: info: CoreCommandRouter::volumioGetState Jun 28 15:46:41 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:41 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 28 15:46:41 volumio3 volumio[852]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Jun 28 15:46:42 volumio3 volumio[852]: info: go-librespot daemon successfully initialized Jun 28 15:46:42 volumio3 sudo[1167]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=pi,password=js3gr40,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.99.31/bu/music /mnt/NAS/rpi4-2 Jun 28 15:46:42 volumio3 sudo[1167]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:42 volumio3 kernel: CIFS: Attempting to mount //192.168.99.31/bu/music Jun 28 15:46:42 volumio3 sudo[1167]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:42 volumio3 kernel: CIFS: VFS: cifs_mount failed w/return code = -5 Jun 28 15:46:42 volumio3 volumio[852]: info: Cannot mount NAS rpi4-2 at system boot, trial number 2 ,retrying in 5 seconds Jun 28 15:46:43 volumio3 sudo[1187]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 28 15:46:43 volumio3 sudo[1187]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:43 volumio3 sudo[1187]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:43 volumio3 sudo[1189]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 28 15:46:43 volumio3 sudo[1189]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:43 volumio3 sudo[1189]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:43 volumio3 sudo[1193]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 28 15:46:43 volumio3 sudo[1193]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:43 volumio3 systemd[1]: Started UPnP Renderer front-end to MPD. Jun 28 15:46:43 volumio3 sudo[1193]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:43 volumio3 volumio[852]: info: Upmpdcli Daemon Started Jun 28 15:46:43 volumio3 volumio[1195]: Generating RSA private key, 4096 bit long modulus (2 primes) Jun 28 15:46:45 volumio3 volumio[852]: info: Initializing connection to go-librespot Websocket Jun 28 15:46:45 volumio3 go-librespot[1109]: time="2025-06-28T15:46:45+02:00" level=debug msg="new websocket client" Jun 28 15:46:45 volumio3 volumio[852]: info: Connection to go-librespot Websocket established Jun 28 15:46:45 volumio3 volumio[852]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 volumio[852]: Cannot compose Albumart path Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=debug msg="handling transfer player command from e05e8a9997501c10f47b82db44e017e80a13063b" Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWSY75PtDqTkW" Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=trace msg="fetched new page 0 with 61 items (list: 61)" uri="spotify:playlist:37i9dQZF1DWSY75PtDqTkW" Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=debug msg="loading track (paused: true, position: 225354ms)" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=trace msg="emitting websocket event: will_play" Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=debug msg="selected format OGG_VORBIS_320 (14381a669866f406ce793f91b7b44d83be5b1a31)" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:46 volumio3 go-librespot[1109]: time="2025-06-28T15:46:46+02:00" level=debug msg="requested aes key for file 14381a669866f406ce793f91b7b44d83be5b1a31, gid: 3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1383" Jun 28 15:46:47 volumio3 volumio[852]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3hJLKtTpgct9Y9wKww0BiR","play_origin":"playlist/ondemand"}} Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="fetched first chunk of 21, total size is 10596922 bytes" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 sudo[1215]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=pi,password=js3gr40,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.99.31/bu/music /mnt/NAS/rpi4-2 Jun 28 15:46:47 volumio3 sudo[1215]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 15:46:47 volumio3 kernel: CIFS: Attempting to mount //192.168.99.31/bu/music Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1138" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 kernel: CIFS: VFS: cifs_mount failed w/return code = -5 Jun 28 15:46:47 volumio3 sudo[1215]: pam_unix(sudo:session): session closed for user root Jun 28 15:46:47 volumio3 volumio[852]: info: Cannot mount NAS rpi4-2 at system boot, trial number 3 ,retrying in 5 seconds Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="fetched chunk 18/20, size: 524288" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="fetched chunk 16/20, size: 524288" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="fetched chunk 15/20, size: 524288" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=trace msg="seek to 225354ms (diff: 134ms, samples: 9938111, bytes: 8243202)" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="created new output device" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=info msg="loaded track \"Miss You - Remastered\" (paused: true, position: 225354ms, duration: 288666ms, prefetched: false)" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=trace msg="emitting websocket event: metadata" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=trace msg="emitting websocket event: active" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="sending successful reply for dealer request" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 28 15:46:47 volumio3 volumio[852]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3hJLKtTpgct9Y9wKww0BiR","name":"Miss You - Remastered","artist_names":["The Rolling Stones"],"album_name":"Some Girls","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0205c7aec05eabf142cc33b936","position":225354,"duration":288666,"release_date":"year:1978 month:6 day:9","track_number":1,"disc_number":1}} Jun 28 15:46:47 volumio3 volumio[852]: SPOTIFY: received: {"type":"active","data":null} Jun 28 15:46:47 volumio3 volumio[852]: info: Aligning Spotify Volume to Volumio Volume Jun 28 15:46:47 volumio3 volumio[852]: info: CoreCommandRouter::volumioGetState Jun 28 15:46:47 volumio3 volumio[852]: info: CorePlayQueue::getTrack 0 Jun 28 15:46:47 volumio3 volumio[852]: info: Setting Spotify Volume from Volumio: 78 Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="fetched chunk 17/20, size: 524288" uri="spotify:track:3hJLKtTpgct9Y9wKww0BiR" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 28 15:46:47 volumio3 go-librespot[1109]: time="2025-06-28T15:46:47+02:00" level=trace msg="emitting websocket event: paused" Jun 28 15:46:47 volumio3 volumio[852]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3hJLKtTpgct9Y9wKww0BiR","play_origin":"playlist/ondemand"}} Jun 28 15:46:47 volumio3 volumio[852]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 28 15:46:47 volumio3 volumio[852]: TypeError: Cannot read property 'service' of undefined Jun 28 15:46:47 volumio3 volumio[852]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Jun 28 15:46:47 volumio3 volumio[852]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Jun 28 15:46:47 volumio3 volumio[852]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Jun 28 15:46:47 volumio3 volumio[852]: at WebSocket.emit (events.js:315:20) Jun 28 15:46:47 volumio3 volumio[852]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jun 28 15:46:47 volumio3 volumio[852]: at Receiver.emit (events.js:315:20) Jun 28 15:46:47 volumio3 volumio[852]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jun 28 15:46:47 volumio3 volumio[852]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 28 15:46:47 volumio3 volumio[852]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 28 15:46:47 volumio3 volumio[852]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 28 15:46:47 volumio3 volumio[852]: at writeOrBuffer (internal/streams/writable.js:358:12) Jun 28 15:46:47 volumio3 volumio[852]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jun 28 15:46:47 volumio3 volumio[852]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jun 28 15:46:47 volumio3 volumio[852]: at Socket.emit (events.js:315:20) Jun 28 15:46:47 volumio3 volumio[852]: at addChunk (internal/streams/readable.js:309:12) Jun 28 15:46:47 volumio3 volumio[852]: at readableAddChunk (internal/streams/readable.js:284:9) Jun 28 15:46:47 volumio3 volumio[852]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 28 15:46:48 volumio3 systemd[1]: systemd-fsckd.service: Succeeded. Jun 28 15:46:48 volumio3 sudo[1230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-28 15:45 Jun 28 15:46:48 volumio3 sudo[1230]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 04:52:53 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="a72866a0de4045751d03a035de6290e1"