-- Logs begin at Thu 2019-02-14 10:11:59 GMT, end at Sun 2025-06-22 19:34:58 BST. -- Jun 22 19:34:39 volumiopi3 systemd-timedated[982]: Changed local time to Sun Jun 22 19:34:39 2025 Jun 22 19:34:39 volumiopi3 sudo[980]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:39 volumiopi3 volumio-time-update[577]: volumio-time-update-util: System time updated successfully. Jun 22 19:34:39 volumiopi3 systemd[1]: Starting Daily apt download activities... Jun 22 19:34:39 volumiopi3 systemd[1]: Started Volumio Time Update Utility. Jun 22 19:34:40 volumiopi3 systemd[1]: apt-daily.service: Succeeded. Jun 22 19:34:40 volumiopi3 systemd[1]: Started Daily apt download activities. Jun 22 19:34:40 volumiopi3 systemd[1]: Starting Daily apt upgrade and clean activities... Jun 22 19:34:40 volumiopi3 nmbd[691]: [2025/06/22 19:34:40.121826, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 22 19:34:40 volumiopi3 systemd[1]: Started Samba NMB Daemon. Jun 22 19:34:40 volumiopi3 nmbd[691]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jun 22 19:34:40 volumiopi3 systemd[1]: Starting Samba Winbind Daemon... Jun 22 19:34:40 volumiopi3 winbindd[1034]: [2025/06/22 19:34:40.471827, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jun 22 19:34:40 volumiopi3 winbindd[1034]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jun 22 19:34:40 volumiopi3 winbindd[1034]: [2025/06/22 19:34:40.502217, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 22 19:34:40 volumiopi3 winbindd[1034]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jun 22 19:34:40 volumiopi3 systemd[1]: Started Samba Winbind Daemon. Jun 22 19:34:40 volumiopi3 systemd[1]: Starting Samba SMB Daemon... Jun 22 19:34:40 volumiopi3 volumio-remote-updater[583]: [2025-06-22 19:34:40] [connect] Successful connection Jun 22 19:34:40 volumiopi3 systemd[1]: apt-daily-upgrade.service: Succeeded. Jun 22 19:34:40 volumiopi3 systemd[1]: Started Daily apt upgrade and clean activities. Jun 22 19:34:40 volumiopi3 volumio[958]: info: ------------------------------------------- Jun 22 19:34:41 volumiopi3 volumio[958]: info: ----- Volumio3 ---- Jun 22 19:34:41 volumiopi3 volumio[958]: info: ------------------------------------------- Jun 22 19:34:41 volumiopi3 volumio[958]: info: ----- System startup ---- Jun 22 19:34:41 volumiopi3 volumio[958]: info: ------------------------------------------- Jun 22 19:34:41 volumiopi3 smbd[1074]: [2025/06/22 19:34:41.113163, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 22 19:34:41 volumiopi3 systemd[1]: Started Samba SMB Daemon. Jun 22 19:34:41 volumiopi3 smbd[1074]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jun 22 19:34:41 volumiopi3 systemd[1]: Reached target Multi-User System. Jun 22 19:34:41 volumiopi3 systemd[1]: Reached target Graphical Interface. Jun 22 19:34:41 volumiopi3 systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 22 19:34:41 volumiopi3 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jun 22 19:34:41 volumiopi3 systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 22 19:34:41 volumiopi3 systemd[1]: Startup finished in 13.221s (kernel) + 28.142s (userspace) = 41.364s. Jun 22 19:34:42 volumiopi3 volumio[958]: info: MYVOLUMIO Environment detected Jun 22 19:34:42 volumiopi3 volumio[958]: info: Plugin folders cleanup Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning into folder /volumio/app/plugins/ Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning category audio_interface Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning category miscellanea Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning category music_service Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning category plugins.json Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning category system_controller Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning category user_interface Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning into folder /data/plugins/ Jun 22 19:34:42 volumiopi3 volumio[958]: info: Scanning category music_service Jun 22 19:34:42 volumiopi3 volumio[958]: info: Plugin folders cleanup completed Jun 22 19:34:42 volumiopi3 volumio[958]: info: ------------------------------------------- Jun 22 19:34:42 volumiopi3 volumio[958]: info: ----- Core plugins startup ---- Jun 22 19:34:42 volumiopi3 volumio[958]: info: ------------------------------------------- Jun 22 19:34:42 volumiopi3 volumio[958]: info: Loading plugins from folder /volumio/app/plugins/ Jun 22 19:34:42 volumiopi3 volumio[958]: info: Adding plugin upnp to MyMusic Plugins Jun 22 19:34:42 volumiopi3 volumio[958]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 22 19:34:42 volumiopi3 volumio[958]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 22 19:34:42 volumiopi3 volumio[958]: info: Loading plugins from folder /data/plugins/ Jun 22 19:34:42 volumiopi3 volumio[958]: info: Loading plugin "system"... Jun 22 19:34:42 volumiopi3 volumio[958]: info: Loading plugin "appearance"... Jun 22 19:34:43 volumiopi3 volumio[958]: info: Loading plugin "network"... Jun 22 19:34:43 volumiopi3 volumio[958]: info: Refreshing Cached IP Addresses Jun 22 19:34:43 volumiopi3 sudo[1111]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 22 19:34:43 volumiopi3 sudo[1111]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:43 volumiopi3 sudo[1111]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:43 volumiopi3 sudo[1113]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 22 19:34:43 volumiopi3 sudo[1113]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:43 volumiopi3 sudo[1113]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:43 volumiopi3 volumio[958]: info: Loading plugin "services"... Jun 22 19:34:43 volumiopi3 volumio[958]: info: Loading plugin "alsa_controller"... Jun 22 19:34:43 volumiopi3 sudo[1126]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 22 19:34:43 volumiopi3 sudo[1126]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:43 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 22 19:34:43 volumiopi3 volumio[958]: info: Loading plugin "wizard"... Jun 22 19:34:43 volumiopi3 volumio[958]: info: Loading plugin "networkfs"... Jun 22 19:34:43 volumiopi3 volumio[958]: info: Starting Udev Watcher for removable devices Jun 22 19:34:43 volumiopi3 sudo[1139]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=john,password=Belfast@1968,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.104/music/ /mnt/NAS/Synology Jun 22 19:34:43 volumiopi3 sudo[1139]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:44 volumiopi3 volumio[958]: info: Ignoring mount for partition: boot Jun 22 19:34:44 volumiopi3 volumio[958]: info: Ignoring mount for partition: volumio Jun 22 19:34:44 volumiopi3 volumio[958]: info: Ignoring mount for partition: volumio_data Jun 22 19:34:44 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 22 19:34:44 volumiopi3 volumio[958]: info: Loading plugin "volumio_command_line_client"... Jun 22 19:34:44 volumiopi3 volumio[958]: info: Loading plugin "upnp"... Jun 22 19:34:44 volumiopi3 volumio[958]: info: [1750617284070] Starting Upmpd Daemon Jun 22 19:34:44 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 22 19:34:44 volumiopi3 volumio[958]: info: Loading plugin "my_music"... Jun 22 19:34:44 volumiopi3 volumio[958]: info: Loading plugin "mpd"... Jun 22 19:34:44 volumiopi3 kernel: Key type cifs.spnego registered Jun 22 19:34:44 volumiopi3 kernel: Key type cifs.idmap registered Jun 22 19:34:44 volumiopi3 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 22 19:34:44 volumiopi3 kernel: CIFS: Attempting to mount //192.168.0.104/music Jun 22 19:34:44 volumiopi3 kernel: cryptd: max_cpu_qlen set to 1000 Jun 22 19:34:44 volumiopi3 volumio[958]: info: Loading plugin "upnp_browser"... Jun 22 19:34:45 volumiopi3 sudo[1139]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:45 volumiopi3 volumio[958]: info: Loading plugin "alarm-clock"... Jun 22 19:34:45 volumiopi3 volumio[958]: info: Loading plugin "airplay_emulation"... Jun 22 19:34:45 volumiopi3 volumio[958]: info: Starting Shairport Sync Jun 22 19:34:45 volumiopi3 volumio[958]: info: Loading plugin "last_100"... Jun 22 19:34:45 volumiopi3 volumio[958]: info: Loading plugin "webradio"... Jun 22 19:34:45 volumiopi3 volumio[958]: info: Loading plugin "i2s_dacs"... Jun 22 19:34:45 volumiopi3 volumio[958]: info: Loading plugin "volumiodiscovery"... Jun 22 19:34:45 volumiopi3 volumio[958]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 22 19:34:45 volumiopi3 volumio[958]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 22 19:34:45 volumiopi3 volumio[958]: *** WARNING *** For more information see Jun 22 19:34:45 volumiopi3 volumio[958]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 22 19:34:45 volumiopi3 volumio[958]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 22 19:34:45 volumiopi3 node[958]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 22 19:34:45 volumiopi3 volumio[958]: *** WARNING *** For more information see Jun 22 19:34:45 volumiopi3 node[958]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 22 19:34:45 volumiopi3 node[958]: *** WARNING *** For more information see Jun 22 19:34:45 volumiopi3 node[958]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 22 19:34:45 volumiopi3 node[958]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 22 19:34:45 volumiopi3 node[958]: *** WARNING *** For more information see Jun 22 19:34:45 volumiopi3 volumio[958]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 22 19:34:45 volumiopi3 volumio[958]: info: Discovery: Started advertising with name: VolumioPi3 Jun 22 19:34:45 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 22 19:34:45 volumiopi3 volumio[958]: info: Loading plugin "spop"... Jun 22 19:34:45 volumiopi3 systemd[1]: systemd-fsckd.service: Succeeded. Jun 22 19:34:47 volumiopi3 volumio[958]: info: Loading plugin "outputs"... Jun 22 19:34:47 volumiopi3 volumio[958]: info: Loading plugin "albumart"... Jun 22 19:34:47 volumiopi3 volumio[958]: info: Plugin example_plugin is not enabled Jun 22 19:34:47 volumiopi3 volumio[958]: info: Loading plugin "inputs"... Jun 22 19:34:47 volumiopi3 volumio[958]: info: Loading plugin "updater_comm"... Jun 22 19:34:47 volumiopi3 sh[484]: timed out Jun 22 19:34:47 volumiopi3 dhcpcd[514]: timed out Jun 22 19:34:47 volumiopi3 sh[484]: dhcpcd exited Jun 22 19:34:47 volumiopi3 dhcpcd[514]: dhcpcd exited Jun 22 19:34:47 volumiopi3 sh[484]: ifup: failed to bring up eth0 Jun 22 19:34:47 volumiopi3 systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Jun 22 19:34:47 volumiopi3 systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Jun 22 19:34:47 volumiopi3 sudo[1126]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:47 volumiopi3 volumio[958]: info: Plugin mpdemulation is not enabled Jun 22 19:34:47 volumiopi3 volumio[958]: info: Loading plugin "rest_api"... Jun 22 19:34:47 volumiopi3 volumio[958]: info: Loading plugin "websocket"... Jun 22 19:34:47 volumiopi3 volumio[958]: info: Starting Socket.io Server version 2.3.0 Jun 22 19:34:47 volumiopi3 volumio[958]: info: Loading i18n strings for locale en Jun 22 19:34:47 volumiopi3 volumio[958]: Updating browse sources language Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 19:34:47 volumiopi3 volumio[958]: Forking 3 albumart workers Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::initPlayerControls Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 22 19:34:47 volumiopi3 volumio[958]: Express server listening on port 3000 Jun 22 19:34:47 volumiopi3 volumio[958]: [Metrics] WebUI: 8s 117.43ms Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreStateMachine::resetVolumioState Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreStateMachine::getcurrentVolume Jun 22 19:34:47 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioRetrievevolume Jun 22 19:34:48 volumiopi3 volumio[958]: info: Volumio Network Manager: Network status updated: 2 Jun 22 19:34:48 volumiopi3 volumio[958]: info: Reloading queue from file Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 19:34:48 volumiopi3 volumio[958]: info: Setting Device type: Raspberry PI Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreStateMachine::setRepeat null single undefined Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreStateMachine::pushState Jun 22 19:34:48 volumiopi3 volumio[958]: info: CorePlayQueue::getTrack 0 Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioPushState Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreStateMachine::setRandom null Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreStateMachine::pushState Jun 22 19:34:48 volumiopi3 volumio[958]: info: CorePlayQueue::getTrack 0 Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioPushState Jun 22 19:34:48 volumiopi3 volumio[958]: info: Completed loading Core Plugins Jun 22 19:34:48 volumiopi3 volumio[958]: info: Preparing to generate the ALSA configuration file Jun 22 19:34:48 volumiopi3 volumio[958]: info: VolumeController:: Volume=87 Mute =false Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreStateMachine::pushState Jun 22 19:34:48 volumiopi3 volumio[958]: info: CorePlayQueue::getTrack 0 Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioPushState Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreStateMachine::updateTrackBlock Jun 22 19:34:48 volumiopi3 volumio[958]: info: CorePlayQueue::getTrackBlock Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioRetrievevolume Jun 22 19:34:48 volumiopi3 volumio[958]: info: Asound.conf file unchanged, so no further update is needed Jun 22 19:34:48 volumiopi3 volumio[958]: info: Output device has changed, restarting MPD Jun 22 19:34:48 volumiopi3 volumio[958]: info: Output device has changed, restarting Shairport Sync Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 19:34:48 volumiopi3 sudo[1219]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 22 19:34:48 volumiopi3 sudo[1219]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:48 volumiopi3 sudo[1221]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 22 19:34:48 volumiopi3 sudo[1219]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:48 volumiopi3 sudo[1221]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:48 volumiopi3 volumio[958]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 22 19:34:48 volumiopi3 systemd[1]: Stopping Music Player Daemon... Jun 22 19:34:48 volumiopi3 volumio[958]: info: ___________ START PLUGINS ___________ Jun 22 19:34:48 volumiopi3 volumio[958]: info: ControllerMpd::onStart: Initializing MPD Jun 22 19:34:48 volumiopi3 volumio[958]: info: Creating MPD Configuration file Jun 22 19:34:48 volumiopi3 sudo[1228]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 22 19:34:48 volumiopi3 sudo[1228]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:48 volumiopi3 sudo[1228]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 22 19:34:48 volumiopi3 volumio[958]: info: [1750617288613] CoreMusicLibrary::Adding element Media Servers Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 19:34:48 volumiopi3 volumio[958]: Starting albumart workers Jun 22 19:34:48 volumiopi3 volumio[958]: Starting albumart workers Jun 22 19:34:48 volumiopi3 volumio[958]: Starting albumart workers Jun 22 19:34:48 volumiopi3 sudo[1231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 22 19:34:48 volumiopi3 sudo[1231]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 19:34:48 volumiopi3 systemd[1]: mpd.service: Succeeded. Jun 22 19:34:48 volumiopi3 systemd[1]: Stopped Music Player Daemon. Jun 22 19:34:48 volumiopi3 volumio[958]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 19:34:48 volumiopi3 systemd[1]: Starting Music Player Daemon... Jun 22 19:34:48 volumiopi3 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Jun 22 19:34:48 volumiopi3 systemd[1]: mpd.service: Succeeded. Jun 22 19:34:48 volumiopi3 systemd[1]: Stopped Music Player Daemon. Jun 22 19:34:48 volumiopi3 systemd[1]: Starting Music Player Daemon... Jun 22 19:34:48 volumiopi3 volumio[958]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 22 19:34:48 volumiopi3 volumio[958]: info: [1750617288791] CoreMusicLibrary::Adding element Last_100 Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 22 19:34:48 volumiopi3 volumio[958]: info: [1750617288794] CoreMusicLibrary::Adding element Webradio Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 22 19:34:48 volumiopi3 volumio[958]: info: Initializing BBC Radios Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 19:34:48 volumiopi3 volumio[958]: info: Creating Spotify config file Jun 22 19:34:48 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:48 volumiopi3 sudo[1240]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 22 19:34:48 volumiopi3 sudo[1240]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:48 volumiopi3 sudo[1240]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:49 volumiopi3 volumio[958]: info: Volumio Calling Home Jun 22 19:34:49 volumiopi3 volumio[958]: info: MPD Permissions set Jun 22 19:34:49 volumiopi3 volumio[958]: info: MPD Permissions set Jun 22 19:34:49 volumiopi3 volumio[958]: info: Spotify config file written Jun 22 19:34:49 volumiopi3 sudo[1266]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 22 19:34:49 volumiopi3 sudo[1266]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:49 volumiopi3 volumio[958]: info: Discovery: adding c7e7b74d-5a44-46a0-983d-f772f2f1e2ee Jun 22 19:34:49 volumiopi3 volumio[958]: info: Discovery: Found device VolumioPi3 Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioGetState Jun 22 19:34:49 volumiopi3 volumio[958]: info: CorePlayQueue::getTrack 0 Jun 22 19:34:49 volumiopi3 systemd[1]: Started go-librespot Daemon. Jun 22 19:34:49 volumiopi3 go-librespot[1268]: Librespot-go daemon starting... Jun 22 19:34:49 volumiopi3 sudo[1266]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:49 volumiopi3 volumio[958]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 19:34:49 volumiopi3 systemd[1]: systemd-hostnamed.service: Succeeded. Jun 22 19:34:49 volumiopi3 volumio[958]: info: Volumio called home Jun 22 19:34:49 volumiopi3 volumio[958]: info: VolumeController:: Volume=87 Mute =false Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreStateMachine::pushState Jun 22 19:34:49 volumiopi3 volumio[958]: info: CorePlayQueue::getTrack 0 Jun 22 19:34:49 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioPushState Jun 22 19:34:49 volumiopi3 volumio[958]: info: Starting Shairport Sync Jun 22 19:34:50 volumiopi3 volumio[958]: info: Starting Shairport Sync Jun 22 19:34:50 volumiopi3 volumio[958]: info: Starting Shairport Sync Jun 22 19:34:50 volumiopi3 sudo[1303]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 22 19:34:50 volumiopi3 sudo[1303]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:50 volumiopi3 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 22 19:34:50 volumiopi3 sudo[1305]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 22 19:34:50 volumiopi3 systemd[1]: shairport-sync.service: Succeeded. Jun 22 19:34:50 volumiopi3 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 22 19:34:50 volumiopi3 sudo[1305]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:50 volumiopi3 sudo[1308]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 22 19:34:50 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioGetState Jun 22 19:34:50 volumiopi3 sudo[1308]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:50 volumiopi3 volumio[958]: info: CorePlayQueue::getTrack 0 Jun 22 19:34:50 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:50+01:00" level=info msg="generated new device id: be1865ed55cc1d25ec744214d4973f8cdaf2d599" Jun 22 19:34:50 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:50+01:00" level=debug msg="stored credentials found for 1188447904" Jun 22 19:34:50 volumiopi3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 22 19:34:50 volumiopi3 sudo[1303]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:50 volumiopi3 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 22 19:34:50 volumiopi3 systemd[1]: shairport-sync.service: Succeeded. Jun 22 19:34:50 volumiopi3 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 22 19:34:50 volumiopi3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 22 19:34:50 volumiopi3 sudo[1305]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:50 volumiopi3 sudo[1308]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:50 volumiopi3 volumio[958]: info: Shairport-Sync Started Jun 22 19:34:50 volumiopi3 volumio[958]: Error adding Membership: Error: addMembership EINVAL Jun 22 19:34:50 volumiopi3 volumio[958]: info: Shairport-Sync Started Jun 22 19:34:50 volumiopi3 volumio[958]: info: Shairport-Sync Started Jun 22 19:34:50 volumiopi3 volumio[958]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 22 19:34:50 volumiopi3 volumio[958]: SPOTIFY: BQCf660LVWy1YlVqggTGms4O1yW_tnMs6lIum5dLAnA2xwluvX9K6o6r6DNxP8wHPF-ygi7eS8ywO7jfTS22RvA05rGZsfmLhT9Zify_nF_xtf9lKrvHFQ25Czep0QoX01bDSI1tQ4YRZsaHz-70KzkDhRvATkcuzouCuaiU300ZUFxxFcIZSWn-Emj7vKLO1_hxG4Lt7VcibXF45c2mJ7leM_T2qyIfJ18X0LvoD9GrdIzkW-7pDPsCQac0oHTYB8R_FJbRv5iCG5FDN4KztfAXGY8 Jun 22 19:34:50 volumiopi3 volumio[958]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 22 19:34:50 volumiopi3 volumio[958]: info: New Spotify access token = BQCf660LVWy1YlVqggTGms4O1yW_tnMs6lIum5dLAnA2xwluvX9K6o6r6DNxP8wHPF-ygi7eS8ywO7jfTS22RvA05rGZsfmLhT9Zify_nF_xtf9lKrvHFQ25Czep0QoX01bDSI1tQ4YRZsaHz-70KzkDhRvATkcuzouCuaiU300ZUFxxFcIZSWn-Emj7vKLO1_hxG4Lt7VcibXF45c2mJ7leM_T2qyIfJ18X0LvoD9GrdIzkW-7pDPsCQac0oHTYB8R_FJbRv5iCG5FDN4KztfAXGY8 Jun 22 19:34:50 volumiopi3 volumio[958]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 22 19:34:50 volumiopi3 volumio[958]: SPOTIFY: User informations: {"country":"GB","display_name":"1188447904","email":"john3994@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/1188447904"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/1188447904","id":"1188447904","images":[],"product":"premium","type":"user","uri":"spotify:user:1188447904"} Jun 22 19:34:50 volumiopi3 volumio[958]: info: Spotify Successfully logged in Jun 22 19:34:50 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 22 19:34:50 volumiopi3 volumio[958]: info: [1750617290529] CoreMusicLibrary::Adding element Spotify Jun 22 19:34:50 volumiopi3 volumio[958]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 19:34:50 volumiopi3 volumio[958]: Cannot find translation for source Spotify Jun 22 19:34:50 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:50+01:00" level=debug msg="obtained new client token: AAB5yPHaQSDq2wjzhTNWPKWhhtSoomhHVy6+P4xGTeNHn7uqcRE7/vX49wjCY0Nfjy8CN8VIg+PPlvRu9xHQE3f36pPNBTMWjtks/Lh9luUmgQYbnYXgBw/1s4WptvGcTpl0oQfJUepiE7xf0TTyXEA8DOEIYOCnYfKDu8ThWKYhiT52KAeyTLYHr/Ubt28ycHqMABEEgbxNbckeep/7KjWmLjeh4e/+eiuHfll8UEkDWBzFwNznIyKZxc+SwA==" Jun 22 19:34:50 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:50+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 22 19:34:50 volumiopi3 mpd[1252]: Jun 22 19:34 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 22 19:34:50 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:50+01:00" level=debug msg="completed keyexchange" Jun 22 19:34:51 volumiopi3 systemd[1]: Started Music Player Daemon. Jun 22 19:34:51 volumiopi3 sudo[1221]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:51 volumiopi3 sudo[1231]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:51 volumiopi3 volumio[958]: info: Completed starting Core Plugins Jun 22 19:34:51 volumiopi3 volumio[958]: info: ------------------------------------------- Jun 22 19:34:51 volumiopi3 volumio[958]: info: ----- MyVolumio plugins startup ---- Jun 22 19:34:51 volumiopi3 volumio[958]: info: ------------------------------------------- Jun 22 19:34:51 volumiopi3 volumio[958]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 22 19:34:51 volumiopi3 volumio[958]: error: MPD error: The expression evaluated to a falsy value: Jun 22 19:34:51 volumiopi3 volumio[958]: assert.ok(self.idling) Jun 22 19:34:51 volumiopi3 volumio[958]: error: The expression evaluated to a falsy value: Jun 22 19:34:51 volumiopi3 volumio[958]: assert.ok(self.idling) Jun 22 19:34:51 volumiopi3 volumio[958]: info: MPD running with PID1252 Jun 22 19:34:51 volumiopi3 volumio[958]: ,establishing connection Jun 22 19:34:51 volumiopi3 volumio[958]: error: updateQueue error: null Jun 22 19:34:51 volumiopi3 volumio[958]: error: updateQueue error: null Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="completed challenge" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="authenticated as 1188447904" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="authenticated as 1188447904" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" 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]" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="dealer connection opened" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 22 19:34:51 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:51+01:00" level=debug msg="received connection id: OTQ2ZWYyYzItZjExMS00NjM0LWEyZjEtMjQxZmY3YTYxODNkK2RlYWxlcit0Y3A6Ly8wYWNhNDE3Zi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArRTY3MjRDMThGOUM5NkQxQTIyMTg5QUM4MDM5NjFBRTRBQzhGNUYwOTgwQzZERUEwRkRBNjFGREUwNkQ0QTUwRQ==" Jun 22 19:34:52 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:52+01:00" level=debug msg="put connect state because NEW_DEVICE" Jun 22 19:34:52 volumiopi3 volumio[958]: info: go-librespot daemon successfully initialized Jun 22 19:34:54 volumiopi3 sudo[1341]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 22 19:34:54 volumiopi3 sudo[1341]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:54 volumiopi3 sudo[1341]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:54 volumiopi3 sudo[1343]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 22 19:34:54 volumiopi3 sudo[1343]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:54 volumiopi3 sudo[1343]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:54 volumiopi3 sudo[1347]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 22 19:34:54 volumiopi3 sudo[1347]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 19:34:54 volumiopi3 systemd[1]: Started UPnP Renderer front-end to MPD. Jun 22 19:34:54 volumiopi3 sudo[1347]: pam_unix(sudo:session): session closed for user root Jun 22 19:34:54 volumiopi3 volumio[958]: info: Upmpdcli Daemon Started Jun 22 19:34:54 volumiopi3 volumio[1349]: Generating RSA private key, 4096 bit long modulus (2 primes) Jun 22 19:34:54 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:54+01:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Jun 22 19:34:54 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:54+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 160" Jun 22 19:34:55 volumiopi3 volumio-remote-updater[583]: [2025-06-22 19:34:55] [connect] Successful connection Jun 22 19:34:55 volumiopi3 volumio-remote-updater[583]: [2025-06-22 19:34:55] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1750617295 101 Jun 22 19:34:55 volumiopi3 volumio[958]: 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: 2 Jun 22 19:34:55 volumiopi3 volumio[958]: info: Initializing connection to go-librespot Websocket Jun 22 19:34:55 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:55+01:00" level=debug msg="new websocket client" Jun 22 19:34:55 volumiopi3 volumio[958]: info: Connection to go-librespot Websocket established Jun 22 19:34:56 volumiopi3 volumio[958]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 22 19:34:56 volumiopi3 volumio[1349]: ..................++++ Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="handling transfer player command from 3499a0f2943eb242a0fd891db6e04dee029e9b0a" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=trace msg="fetched new page 0 with 65 items (list: 65)" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="shuffled context with seed 1462908933650006981 (len: 65, keep: 56)" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="loading track spotify:track:5ikdUUm6JbnEVnp35c7dvy (paused: true, position: 8309ms)" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=trace msg="emitting websocket event: will_play" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5ikdUUm6JbnEVnp35c7dvy" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="requested aes key for file cf2679bd8a0832a57a81ed144056615634910938, gid: 5ikdUUm6JbnEVnp35c7dvy" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1343" Jun 22 19:34:57 volumiopi3 volumio[958]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5ikdUUm6JbnEVnp35c7dvy","play_origin":"playlist"}} Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1117" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="fetched first chunk of 39, total size is 20210666 bytes" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=trace msg="seek to 8309ms (diff: 155ms, samples: 366426, bytes: 323608)" Jun 22 19:34:57 volumiopi3 kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=info msg="loaded track \"I Am the Resurrection - Remastered 2009\" (uri: spotify:track:5ikdUUm6JbnEVnp35c7dvy, paused: true, position: 8309ms, duration: 492946ms)" Jun 22 19:34:57 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:57+01:00" level=debug msg="fetched chunk 3/38, size: 524288" Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=trace msg="emitting websocket event: metadata" Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=trace msg="emitting websocket event: active" Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=debug msg="sending successful reply for delaer request" Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=debug msg="fetched chunk 2/38, size: 524288" Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=trace msg="emitting websocket event: paused" Jun 22 19:34:58 volumiopi3 go-librespot[1268]: time="2025-06-22T19:34:58+01:00" level=debug msg="fetched chunk 1/38, size: 524288" Jun 22 19:34:58 volumiopi3 volumio[958]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5ikdUUm6JbnEVnp35c7dvy","name":"I Am the Resurrection - Remastered 2009","artist_names":["The Stone Roses"],"album_name":"The Stone Roses","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02cf1f6466a493eb73d6d9d280","position":8309,"duration":492946,"release_date":"year:1989 month:5 day:2","track_number":11,"disc_number":1}} Jun 22 19:34:58 volumiopi3 volumio[958]: SPOTIFY: received: {"type":"active","data":null} Jun 22 19:34:58 volumiopi3 volumio[958]: info: Aligning Spotify Volume to Volumio Volume Jun 22 19:34:58 volumiopi3 volumio[958]: info: CoreCommandRouter::volumioGetState Jun 22 19:34:58 volumiopi3 volumio[958]: info: CorePlayQueue::getTrack 0 Jun 22 19:34:58 volumiopi3 volumio[958]: info: Setting Spotify Volume from Volumio: 87 Jun 22 19:34:58 volumiopi3 volumio[958]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5ikdUUm6JbnEVnp35c7dvy","play_origin":"playlist"}} Jun 22 19:34:58 volumiopi3 volumio[958]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 22 19:34:58 volumiopi3 volumio[958]: TypeError: Cannot read property 'service' of undefined Jun 22 19:34:58 volumiopi3 volumio[958]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Jun 22 19:34:58 volumiopi3 volumio[958]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Jun 22 19:34:58 volumiopi3 volumio[958]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Jun 22 19:34:58 volumiopi3 volumio[958]: at WebSocket.emit (events.js:315:20) Jun 22 19:34:58 volumiopi3 volumio[958]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Jun 22 19:34:58 volumiopi3 volumio[958]: at Receiver.emit (events.js:315:20) Jun 22 19:34:58 volumiopi3 volumio[958]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Jun 22 19:34:58 volumiopi3 volumio[958]: at internal/process/task_queues.js:149:7 Jun 22 19:34:58 volumiopi3 volumio[958]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Jun 22 19:34:58 volumiopi3 volumio[958]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Jun 22 19:34:58 volumiopi3 volumio[958]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jun 22 19:34:58 volumiopi3 volumio[958]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 22 19:34:58 volumiopi3 sudo[1374]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-22 19:33 Jun 22 19:34:58 volumiopi3 sudo[1374]: 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"