-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Tue 2025-07-08 20:19:01 CEST. -- Jul 08 20:18:44 volumio systemd-timedated[996]: Changed local time to Tue Jul 8 20:18:44 2025 Jul 08 20:18:44 volumio sudo[994]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:44 volumio volumio-time-update[574]: volumio-time-update-util: System time updated successfully. Jul 08 20:18:44 volumio systemd[1]: Started Volumio Time Update Utility. Jul 08 20:18:44 volumio systemd[1]: Reached target Multi-User System. Jul 08 20:18:44 volumio systemd[1]: Reached target Graphical Interface. Jul 08 20:18:44 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Jul 08 20:18:44 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jul 08 20:18:44 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Jul 08 20:18:44 volumio systemd[1]: Startup finished in 14.438s (kernel) + 16.652s (userspace) = 31.090s. Jul 08 20:18:44 volumio volumio[876]: info: MYVOLUMIO Environment detected Jul 08 20:18:44 volumio volumio[876]: info: Plugin folders cleanup Jul 08 20:18:44 volumio volumio[876]: info: Scanning into folder /volumio/app/plugins/ Jul 08 20:18:44 volumio volumio[876]: info: Scanning category audio_interface Jul 08 20:18:44 volumio volumio[876]: info: Scanning category miscellanea Jul 08 20:18:44 volumio volumio[876]: info: Scanning category music_service Jul 08 20:18:44 volumio volumio[876]: info: Scanning category plugins.json Jul 08 20:18:44 volumio volumio[876]: info: Scanning category system_controller Jul 08 20:18:44 volumio volumio[876]: info: Scanning category user_interface Jul 08 20:18:44 volumio volumio[876]: info: Scanning into folder /data/plugins/ Jul 08 20:18:44 volumio volumio[876]: info: Scanning category audio_interface Jul 08 20:18:44 volumio volumio[876]: info: Scanning category music_service Jul 08 20:18:44 volumio volumio[876]: info: Plugin folders cleanup completed Jul 08 20:18:44 volumio volumio[876]: info: ------------------------------------------- Jul 08 20:18:44 volumio volumio[876]: info: ----- Core plugins startup ---- Jul 08 20:18:44 volumio volumio[876]: info: ------------------------------------------- Jul 08 20:18:44 volumio volumio[876]: info: Loading plugins from folder /volumio/app/plugins/ Jul 08 20:18:44 volumio volumio[876]: info: Adding plugin upnp to MyMusic Plugins Jul 08 20:18:44 volumio volumio[876]: info: Adding plugin airplay_emulation to MyMusic Plugins Jul 08 20:18:44 volumio volumio[876]: info: Adding plugin upnp_browser to MyMusic Plugins Jul 08 20:18:44 volumio volumio[876]: info: Loading plugins from folder /data/plugins/ Jul 08 20:18:44 volumio volumio[876]: info: Loading plugin "system"... Jul 08 20:18:44 volumio volumio[876]: info: Loading plugin "appearance"... Jul 08 20:18:45 volumio volumio-remote-updater[575]: [2025-07-08 20:18:45] [connect] Successful connection Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "network"... Jul 08 20:18:46 volumio volumio[876]: info: Refreshing Cached IP Addresses Jul 08 20:18:46 volumio sudo[1006]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 08 20:18:46 volumio sudo[1006]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "services"... Jul 08 20:18:46 volumio sudo[1008]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 08 20:18:46 volumio sudo[1008]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:46 volumio sudo[1006]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "alsa_controller"... Jul 08 20:18:46 volumio sudo[1008]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:46 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "wizard"... Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "networkfs"... Jul 08 20:18:46 volumio sudo[1031]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Volumio,password=sdubg^@sdgm6awdHz,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.100/Pobrane/Muzyka/muzyka /mnt/NAS/Muzyka Jul 08 20:18:46 volumio sudo[1031]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:46 volumio volumio[876]: info: Starting Udev Watcher for removable devices Jul 08 20:18:46 volumio sudo[1033]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Volumio,password=sdubg^@sdgm6awdHz,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.100/Pobrane/Muzyka/muzyka jazz /mnt/NAS/Muzyka_jazz Jul 08 20:18:46 volumio sudo[1033]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:46 volumio volumio[876]: info: Ignoring mount for partition: boot Jul 08 20:18:46 volumio volumio[876]: info: Ignoring mount for partition: volumio Jul 08 20:18:46 volumio volumio[876]: info: Ignoring mount for partition: volumio_data Jul 08 20:18:46 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "volumio_command_line_client"... Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "upnp"... Jul 08 20:18:46 volumio volumio[876]: info: [1751998726891] Starting Upmpd Daemon Jul 08 20:18:46 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "my_music"... Jul 08 20:18:46 volumio volumio[876]: info: Loading plugin "mpd"... Jul 08 20:18:47 volumio kernel: Key type cifs.spnego registered Jul 08 20:18:47 volumio kernel: Key type cifs.idmap registered Jul 08 20:18:47 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Jul 08 20:18:47 volumio kernel: CIFS: Attempting to mount //192.168.2.100/Pobrane/Muzyka/muzyka jazz Jul 08 20:18:47 volumio kernel: cryptd: max_cpu_qlen set to 1000 Jul 08 20:18:47 volumio volumio[876]: info: Loading plugin "upnp_browser"... Jul 08 20:18:47 volumio sudo[1033]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:47 volumio kernel: CIFS: Attempting to mount //192.168.2.100/Pobrane/Muzyka/muzyka Jul 08 20:18:47 volumio sudo[1031]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:47 volumio volumio[876]: info: Loading plugin "alarm-clock"... Jul 08 20:18:48 volumio volumio[876]: info: Loading plugin "airplay_emulation"... Jul 08 20:18:48 volumio volumio[876]: info: Starting Shairport Sync Jul 08 20:18:48 volumio volumio[876]: info: Loading plugin "last_100"... Jul 08 20:18:48 volumio volumio[876]: info: Loading plugin "webradio"... Jul 08 20:18:48 volumio volumio[876]: info: Loading plugin "i2s_dacs"... Jul 08 20:18:48 volumio volumio[876]: info: I2S DAC not set, start Auto-detection Jul 08 20:18:48 volumio volumio[876]: info: Loading plugin "volumiodiscovery"... Jul 08 20:18:48 volumio volumio[876]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 08 20:18:48 volumio volumio[876]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 08 20:18:48 volumio volumio[876]: *** WARNING *** For more information see Jul 08 20:18:48 volumio volumio[876]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 08 20:18:48 volumio volumio[876]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 08 20:18:48 volumio volumio[876]: *** WARNING *** For more information see Jul 08 20:18:48 volumio node[876]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 08 20:18:48 volumio node[876]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 08 20:18:48 volumio node[876]: *** WARNING *** For more information see Jul 08 20:18:48 volumio node[876]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 08 20:18:48 volumio node[876]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 08 20:18:48 volumio node[876]: *** WARNING *** For more information see Jul 08 20:18:48 volumio volumio[876]: info: Applying required configuration parameters for plugin volumiodiscovery Jul 08 20:18:48 volumio volumio[876]: info: Discovery: Started advertising with name: Volumio Jul 08 20:18:48 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 08 20:18:48 volumio volumio[876]: info: Loading plugin "spop"... Jul 08 20:18:50 volumio volumio[876]: info: Loading plugin "outputs"... Jul 08 20:18:50 volumio volumio[876]: info: Loading plugin "albumart"... Jul 08 20:18:50 volumio volumio[876]: info: Plugin example_plugin is not enabled Jul 08 20:18:50 volumio volumio[876]: info: Loading plugin "inputs"... Jul 08 20:18:50 volumio volumio[876]: info: Loading plugin "updater_comm"... Jul 08 20:18:50 volumio volumio[876]: info: Plugin mpdemulation is not enabled Jul 08 20:18:50 volumio volumio[876]: info: Loading plugin "rest_api"... Jul 08 20:18:50 volumio volumio[876]: info: Loading plugin "websocket"... Jul 08 20:18:50 volumio volumio[876]: info: Starting Socket.io Server version 2.3.0 Jul 08 20:18:50 volumio volumio[876]: info: Loading plugin "fusiondsp"... Jul 08 20:18:51 volumio volumio[876]: Forking 3 albumart workers Jul 08 20:18:51 volumio volumio[876]: info: Applying required configuration parameters for plugin fusiondsp Jul 08 20:18:51 volumio volumio[876]: info: Loading plugin "rad357pl"... Jul 08 20:18:52 volumio volumio[876]: Starting albumart workers Jul 08 20:18:52 volumio volumio[876]: Starting albumart workers Jul 08 20:18:52 volumio volumio[876]: Starting albumart workers Jul 08 20:18:52 volumio volumio[876]: info: Applying required configuration parameters for plugin rad357pl Jul 08 20:18:52 volumio volumio[876]: info: [1751998732222] [rad357pl] API delay: 5 Jul 08 20:18:52 volumio volumio[876]: info: Loading i18n strings for locale pl Jul 08 20:18:52 volumio volumio[876]: Updating browse sources language Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::initPlayerControls Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 08 20:18:52 volumio volumio[876]: Express server listening on port 3000 Jul 08 20:18:52 volumio volumio[876]: [Metrics] WebUI: 11s 544.15ms Jul 08 20:18:52 volumio volumio[876]: info: CoreStateMachine::resetVolumioState Jul 08 20:18:52 volumio volumio[876]: info: CoreStateMachine::getcurrentVolume Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::volumioRetrievevolume Jul 08 20:18:52 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:52 volumio volumio[876]: info: Volumio Network Manager: Network status updated: 1 Jul 08 20:18:53 volumio volumio[876]: info: Reloading queue from file Jul 08 20:18:53 volumio volumio[876]: info: Setting Device type: Raspberry PI Jul 08 20:18:53 volumio volumio[876]: info: VolumeController:: Volume=36 Mute =false Jul 08 20:18:53 volumio volumio[876]: info: CoreStateMachine::pushState Jul 08 20:18:53 volumio volumio[876]: info: CorePlayQueue::getTrack 0 Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioPushState Jul 08 20:18:53 volumio volumio[876]: info: CoreStateMachine::updateTrackBlock Jul 08 20:18:53 volumio volumio[876]: info: CorePlayQueue::getTrackBlock Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioRetrievevolume Jul 08 20:18:53 volumio volumio[876]: info: CoreStateMachine::setRepeat null single undefined Jul 08 20:18:53 volumio volumio[876]: info: CoreStateMachine::pushState Jul 08 20:18:53 volumio volumio[876]: info: CorePlayQueue::getTrack 0 Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioPushState Jul 08 20:18:53 volumio volumio[876]: info: CoreStateMachine::setRandom null Jul 08 20:18:53 volumio volumio[876]: info: CoreStateMachine::pushState Jul 08 20:18:53 volumio volumio[876]: info: CorePlayQueue::getTrack 0 Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioPushState Jul 08 20:18:53 volumio volumio[876]: info: Completed loading Core Plugins Jul 08 20:18:53 volumio volumio[876]: info: Preparing to generate the ALSA configuration file Jul 08 20:18:53 volumio volumio[876]: info: Discovery: adding 3fe515ff-8757-49e8-874b-1b6dcea823f3 Jul 08 20:18:53 volumio volumio[876]: info: Discovery: Found device Volumio Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioGetState Jul 08 20:18:53 volumio volumio[876]: info: CorePlayQueue::getTrack 0 Jul 08 20:18:53 volumio volumio[876]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Jul 08 20:18:53 volumio volumio[876]: info: Reading ALSA contributions from plugins. Jul 08 20:18:53 volumio volumio[876]: info: Asound.conf file unchanged, so no further update is needed Jul 08 20:18:53 volumio volumio[876]: info: Output device has changed, restarting MPD Jul 08 20:18:53 volumio volumio[876]: info: Output device has changed, restarting Shairport Sync Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:53 volumio sudo[1147]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 08 20:18:53 volumio sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:53 volumio sudo[1147]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:53 volumio sudo[1149]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 08 20:18:53 volumio sudo[1149]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:53 volumio systemd[1]: Stopping Music Player Daemon... Jul 08 20:18:53 volumio volumio[876]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 08 20:18:53 volumio volumio[876]: info: ___________ START PLUGINS ___________ Jul 08 20:18:53 volumio volumio[876]: info: ControllerMpd::onStart: Initializing MPD Jul 08 20:18:53 volumio volumio[876]: info: Creating MPD Configuration file Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 08 20:18:53 volumio sudo[1156]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 20:18:53 volumio volumio[876]: info: [1751998733452] CoreMusicLibrary::Adding element Serwery Mediów Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 20:18:53 volumio sudo[1156]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:53 volumio sudo[1156]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:53 volumio sudo[1158]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 08 20:18:53 volumio sudo[1158]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:53 volumio volumio[876]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:53 volumio volumio[876]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 20:18:53 volumio volumio[876]: info: [1751998733604] CoreMusicLibrary::Adding element Last_100 Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 20:18:53 volumio volumio[876]: info: [1751998733608] CoreMusicLibrary::Adding element Webradio Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 20:18:53 volumio volumio[876]: info: Initializing BBC Radios Jul 08 20:18:53 volumio systemd[1]: mpd.service: Succeeded. Jul 08 20:18:53 volumio systemd[1]: Stopped Music Player Daemon. Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:53 volumio systemd[1]: Starting Music Player Daemon... Jul 08 20:18:53 volumio volumio[876]: info: Creating Spotify config file Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:53 volumio volumio[876]: info: Loading i18n strings for locale pl Jul 08 20:18:53 volumio sudo[1170]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jul 08 20:18:53 volumio sudo[1170]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:53 volumio volumio[876]: info: FusionDsp - mixtype--------------------- Hardware Jul 08 20:18:53 volumio sudo[1170]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 20:18:53 volumio volumio[876]: info: [1751998733860] CoreMusicLibrary::Adding element RADIO 357 Jul 08 20:18:53 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 20:18:53 volumio volumio[876]: Cannot find translation for source RADIO 357 Jul 08 20:18:53 volumio volumio[876]: info: Volumio Calling Home Jul 08 20:18:53 volumio volumio[876]: info: Preparing to generate the ALSA configuration file Jul 08 20:18:54 volumio volumio[876]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Jul 08 20:18:54 volumio volumio[876]: info: Reading ALSA contributions from plugins. Jul 08 20:18:54 volumio volumio[876]: info: MPD Permissions set Jul 08 20:18:54 volumio volumio[876]: info: MPD Permissions set Jul 08 20:18:54 volumio volumio[876]: info: VolumeController:: Volume=36 Mute =false Jul 08 20:18:54 volumio volumio[876]: info: CoreStateMachine::pushState Jul 08 20:18:54 volumio volumio[876]: info: CorePlayQueue::getTrack 0 Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::volumioPushState Jul 08 20:18:54 volumio volumio[876]: info: Spotify config file written Jul 08 20:18:54 volumio sudo[1184]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 08 20:18:54 volumio sudo[1184]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:54 volumio volumio[876]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: No need to fix Spotify hosts Jul 08 20:18:54 volumio systemd[1]: Started go-librespot Daemon. Jul 08 20:18:54 volumio go-librespot[1187]: go-librespot daemon starting... Jul 08 20:18:54 volumio sudo[1184]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:54 volumio volumio[876]: info: Starting Shairport Sync Jul 08 20:18:54 volumio volumio[876]: info: Starting Shairport Sync Jul 08 20:18:54 volumio volumio[876]: info: Starting Shairport Sync Jul 08 20:18:54 volumio sudo[1201]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 08 20:18:54 volumio sudo[1201]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:54 volumio sudo[1203]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 08 20:18:54 volumio sudo[1203]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:54 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 08 20:18:54 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 08 20:18:54 volumio sudo[1206]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 08 20:18:54 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 08 20:18:54 volumio sudo[1206]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::volumioGetState Jul 08 20:18:54 volumio volumio[876]: info: CorePlayQueue::getTrack 0 Jul 08 20:18:54 volumio volumio[876]: info: Asound.conf file unchanged, so no further update is needed Jul 08 20:18:54 volumio volumio[876]: info: Output device has changed, restarting MPD Jul 08 20:18:54 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 08 20:18:54 volumio sudo[1201]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:54 volumio sudo[1213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 08 20:18:54 volumio sudo[1213]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:54 volumio sudo[1213]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:54 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 08 20:18:54 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jul 08 20:18:54 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 08 20:18:54 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 08 20:18:54 volumio volumio[876]: info: Output device has changed, restarting Shairport Sync Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:54 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 08 20:18:54 volumio sudo[1203]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:54 volumio sudo[1216]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 08 20:18:54 volumio sudo[1206]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:54 volumio sudo[1216]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:54 volumio volumio[876]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 08 20:18:54 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Jul 08 20:18:54 volumio systemd[1]: mpd.service: Succeeded. Jul 08 20:18:54 volumio systemd[1]: Stopped Music Player Daemon. Jul 08 20:18:54 volumio volumio[876]: info: MPD Permissions set Jul 08 20:18:54 volumio volumio[876]: info: Shairport-Sync Started Jul 08 20:18:54 volumio volumio[876]: Error adding Membership: Error: addMembership EINVAL Jul 08 20:18:54 volumio volumio[876]: info: Shairport-Sync Started Jul 08 20:18:54 volumio volumio[876]: info: Shairport-Sync Started Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio systemd[1]: Starting Music Player Daemon... Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:54 volumio volumio[876]: info: Starting Shairport Sync Jul 08 20:18:54 volumio sudo[1230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 08 20:18:54 volumio sudo[1230]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:54 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 08 20:18:54 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 08 20:18:54 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 08 20:18:54 volumio go-librespot[1187]: time="2025-07-08T20:18:54+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 20:18:54 volumio go-librespot[1187]: time="2025-07-08T20:18:54+02:00" level=debug msg="app state loaded" Jul 08 20:18:54 volumio go-librespot[1187]: time="2025-07-08T20:18:54+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 20:18:54 volumio sudo[1224]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jul 08 20:18:54 volumio sudo[1224]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:54 volumio sudo[1224]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:55 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 08 20:18:55 volumio sudo[1230]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:55 volumio volumio[876]: info: Shairport-Sync Started Jul 08 20:18:55 volumio volumio[876]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 20:18:55 volumio volumio[876]: SPOTIFY: BQBCdNtf040t6Oa5QWiZbCxND4JMWiXkD8RTEZuDvY_rItZzT4KqxwcMLSwPDvHMNv9IcMt0KRLJDWpW_Nud8H5JuybORO7VrR43yhERq-JBIxXLrwvlY0fg0j6OLrXqpyi3jHdjnL1-T-NX1IkoJxP8X_69SLJfoSrzhjHGw4hxXD2YoD17yGi8eWJpXJPM-OiWidBXGUJ9khTnXv8zj_jutcTOheWju7CT5akL03pGzNJyJeR8c9ZNb7E8M5-1-tvEmWYkNGOfURC2Snki2p-Jcw Jul 08 20:18:55 volumio volumio[876]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 20:18:55 volumio volumio[876]: info: New Spotify access token = BQBCdNtf040t6Oa5QWiZbCxND4JMWiXkD8RTEZuDvY_rItZzT4KqxwcMLSwPDvHMNv9IcMt0KRLJDWpW_Nud8H5JuybORO7VrR43yhERq-JBIxXLrwvlY0fg0j6OLrXqpyi3jHdjnL1-T-NX1IkoJxP8X_69SLJfoSrzhjHGw4hxXD2YoD17yGi8eWJpXJPM-OiWidBXGUJ9khTnXv8zj_jutcTOheWju7CT5akL03pGzNJyJeR8c9ZNb7E8M5-1-tvEmWYkNGOfURC2Snki2p-Jcw Jul 08 20:18:55 volumio volumio[876]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 08 20:18:55 volumio volumio[876]: SPOTIFY: User informations: {"country":"PL","display_name":"wavelet26","email":"wojciech.binek@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/wavelet26"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/wavelet26","id":"wavelet26","images":[],"product":"premium","type":"user","uri":"spotify:user:wavelet26"} Jul 08 20:18:55 volumio volumio[876]: info: Spotify Successfully logged in Jul 08 20:18:55 volumio volumio[876]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 20:18:55 volumio volumio[876]: info: [1751998735336] CoreMusicLibrary::Adding element Spotify Jul 08 20:18:55 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 20:18:55 volumio volumio[876]: Cannot find translation for source RADIO 357 Jul 08 20:18:55 volumio volumio[876]: Cannot find translation for source Spotify Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=info msg="zeroconf server listening on port 40513" Jul 08 20:18:55 volumio volumio[876]: info: Volumio called home Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=debug msg="obtained new client token: AAB/ZDWicPE9yOlbUiQZqhfg8iPXW3DaLomWGZgGuYg0Nl65hWNKm/w1hGkgWUWyhem8EMaVriE37o/v3vkxwmjsZmttBsQaGYVzfvryoHcJG22V+Sp4bx6kYG10ZkExXYca0urgWv4yh9AcmiRXcKx3DvFZ05TJ+PRSCcvRiY1T1r+OwN0yBNNvYhPhbYC3VU2SOS7LiVloR7dCDXqAwqw/d0QsZNb9qHaxt3rUMe9BNkTyDVobau/abw==" Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=debug msg="completed keyexchange" Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=debug msg="completed challenge" Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=info msg="authenticated AP as wavelet26" Jul 08 20:18:55 volumio volumio[876]: info: camilladsp spawned new process with pid 1244, instance 1, run: true Jul 08 20:18:55 volumio volumio[876]: info: camilladsp service started and running in background, instance 1 Jul 08 20:18:55 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 20:18:55 volumio volumio[876]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 <-AAAAAAAAAAAAA Jul 08 20:18:55 volumio volumio[876]: info: FusionDsp loaded Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=info msg="authenticated Login5 as wavelet26" Jul 08 20:18:55 volumio go-librespot[1187]: time="2025-07-08T20:18:55+02:00" level=debug msg="initializing zeroconf session, username: wavelet26" Jul 08 20:18:55 volumio volumio[876]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 20:18:56 volumio sudo[1248]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Jul 08 20:18:56 volumio sudo[1248]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:56 volumio volumio[876]: info: FusionDsp - Reporting Fusion DSP Enabled Jul 08 20:18:56 volumio volumio[876]: info: Adding Signal Path Element [object Object] Jul 08 20:18:56 volumio volumio[876]: info: Adding fusiondspeq DSP Signal Path Element Jul 08 20:18:56 volumio volumio[876]: info: FusionDsp - ---- installed callbackRead Jul 08 20:18:56 volumio volumio[876]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 08 20:18:56 volumio volumio[876]: info: FusionDsp - Effects disabled Jul 08 20:18:56 volumio volumio[876]: error: FusionDsp - WebSocket error: [object Object] Jul 08 20:18:56 volumio volumio[876]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="dealer connection opened" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=trace msg="starting dealer recv loop" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=trace msg="received accesspoint ping" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 242" Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="received connection id: OTZhYzk4MDQtMGYyZS00MGU5LThhMzEtNGIwZjg3NTMyMWQ1K2RlYWxlcit0Y3A6Ly8wYWIxNTFhMC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArODNFNTE3NEIzOEI0NTRGMDI2MDhEMDg1RjU2NzZDRUJGQkI3OUIxRjMzRUFCRUI4QjRGOTAxN0I4OUUxRkZCMg==" Jul 08 20:18:56 volumio systemd[1]: Started FusionDsp Daemon. Jul 08 20:18:56 volumio sudo[1248]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=trace msg="received accesspoint pong ack" Jul 08 20:18:56 volumio kernel: usb 1-1.3: 2:1: cannot get freq at ep 0x1 Jul 08 20:18:56 volumio kernel: usb 1-1.3: 2:1: cannot get freq at ep 0x1 Jul 08 20:18:56 volumio go-librespot[1187]: time="2025-07-08T20:18:56+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 20:18:56 volumio mpd[1234]: Jul 08 20:18 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 08 20:18:56 volumio sudo[1272]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 08 20:18:56 volumio sudo[1272]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:56 volumio sudo[1272]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:56 volumio sudo[1274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 08 20:18:56 volumio sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:56 volumio sudo[1274]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:57 volumio sudo[1278]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jul 08 20:18:57 volumio sudo[1278]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 20:18:57 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Jul 08 20:18:57 volumio sudo[1278]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:57 volumio volumio[876]: info: Upmpdcli Daemon Started Jul 08 20:18:57 volumio volumio[876]: info: go-librespot daemon successfully initialized Jul 08 20:18:57 volumio systemd[1]: Started Music Player Daemon. Jul 08 20:18:57 volumio sudo[1216]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:57 volumio sudo[1158]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:57 volumio sudo[1149]: pam_unix(sudo:session): session closed for user root Jul 08 20:18:57 volumio volumio[876]: info: Completed starting Core Plugins Jul 08 20:18:57 volumio volumio[876]: info: ------------------------------------------- Jul 08 20:18:57 volumio volumio[876]: info: ----- MyVolumio plugins startup ---- Jul 08 20:18:57 volumio volumio[876]: info: ------------------------------------------- Jul 08 20:18:57 volumio volumio[876]: info: [MyVolumio PluginManager] Fetching plans data.... Jul 08 20:18:57 volumio go-librespot[1187]: time="2025-07-08T20:18:57+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 08 20:18:57 volumio go-librespot[1187]: time="2025-07-08T20:18:57+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 330" Jul 08 20:18:57 volumio volumio[876]: error: MPD error: The expression evaluated to a falsy value: Jul 08 20:18:57 volumio volumio[876]: assert.ok(self.idling) Jul 08 20:18:57 volumio volumio[876]: error: The expression evaluated to a falsy value: Jul 08 20:18:57 volumio volumio[876]: assert.ok(self.idling) Jul 08 20:18:57 volumio volumio[876]: error: MPD error: The expression evaluated to a falsy value: Jul 08 20:18:57 volumio volumio[876]: assert.ok(self.idling) Jul 08 20:18:57 volumio volumio[876]: error: The expression evaluated to a falsy value: Jul 08 20:18:57 volumio volumio[876]: assert.ok(self.idling) Jul 08 20:18:57 volumio volumio[876]: info: MPD running with PID1234 Jul 08 20:18:57 volumio volumio[876]: ,establishing connection Jul 08 20:18:57 volumio volumio[876]: error: MPD error: The expression evaluated to a falsy value: Jul 08 20:18:57 volumio volumio[876]: assert.ok(self.idling) Jul 08 20:18:57 volumio volumio[876]: error: The expression evaluated to a falsy value: Jul 08 20:18:57 volumio volumio[876]: assert.ok(self.idling) Jul 08 20:18:57 volumio volumio[876]: error: updateQueue error: null Jul 08 20:18:57 volumio volumio[1280]: Generating RSA private key, 4096 bit long modulus (2 primes) Jul 08 20:18:59 volumio go-librespot[1187]: time="2025-07-08T20:18:59+02:00" level=debug msg="handling transfer player command from 6ff58d252da2f677b6634f94d90c9dd022c25e8f" Jul 08 20:18:59 volumio go-librespot[1187]: time="2025-07-08T20:18:59+02:00" level=debug msg="resolved context of track" uri="spotify:album:5cPHT4yMCfETLRYAoBFcOZ" Jul 08 20:18:59 volumio go-librespot[1187]: time="2025-07-08T20:18:59+02:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:album:5cPHT4yMCfETLRYAoBFcOZ" Jul 08 20:18:59 volumio go-librespot[1187]: time="2025-07-08T20:18:59+02:00" level=debug msg="loading track (paused: false, position: 3046ms)" uri="spotify:track:54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="selected format OGG_VORBIS_320 (1264b195ab28cb4607735b695a88695d95f4f9d4)" uri="spotify:track:54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="requested aes key for file 1264b195ab28cb4607735b695a88695d95f4f9d4, gid: 54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1336" Jul 08 20:19:00 volumio volumio[876]: info: Initializing connection to go-librespot Websocket Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="new websocket client" Jul 08 20:19:00 volumio volumio[876]: info: Connection to go-librespot Websocket established Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1112" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="fetched first chunk of 24, total size is 12285362 bytes" uri="spotify:track:54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=trace msg="seek to 3046ms (diff: 96ms, samples: 134328, bytes: 93447)" uri="spotify:track:54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="created new output device" Jul 08 20:19:00 volumio volumio[876]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=info msg="loaded track \"To Build A Home\" (paused: false, position: 3046ms, duration: 371320ms, prefetched: false)" uri="spotify:track:54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio volumio[876]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 08 20:19:00 volumio volumio[876]: info: camilladsp stopping service pid 1244... Jul 08 20:19:00 volumio systemd[1]: systemd-fsckd.service: Succeeded. Jul 08 20:19:00 volumio volumio[876]: info: camilladsp service terminated, instance 1 Jul 08 20:19:00 volumio volumio[876]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 08 20:19:00 volumio volumio[876]: info: FusionDsp - Effects disabled Jul 08 20:19:00 volumio volumio[876]: info: camilladsp service started and running in background, instance 1 Jul 08 20:19:00 volumio volumio[876]: info: camilladsp spawned new process with pid 1308, instance 1, run: true Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=trace msg="scheduling prefetch in 338s" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=trace msg="emitting websocket event: metadata" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=trace msg="emitting websocket event: active" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="sending successful reply for dealer request" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio volumio[876]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:54KFQB6N4pn926IUUYZGzK","name":"To Build A Home","artist_names":["The Cinematic Orchestra","Patrick Watson"],"album_name":"Ma Fleur","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b4b0deaf4a24a795396a9d24","position":3046,"duration":371320,"release_date":"year:2007 month:5 day:7","track_number":1,"disc_number":1}} Jul 08 20:19:00 volumio volumio[876]: SPOTIFY: received: {"type":"active","data":null} Jul 08 20:19:00 volumio volumio[876]: info: Aligning Spotify Volume to Volumio Volume Jul 08 20:19:00 volumio volumio[876]: info: CoreCommandRouter::volumioGetState Jul 08 20:19:00 volumio volumio[876]: info: CorePlayQueue::getTrack 0 Jul 08 20:19:00 volumio volumio[876]: info: Setting Spotify Volume from Volumio: 36 Jul 08 20:19:00 volumio volumio-remote-updater[575]: [2025-07-08 20:19:00] [connect] Successful connection Jul 08 20:19:00 volumio volumio-remote-updater[575]: [2025-07-08 20:19:00] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1751998740 101 Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:54KFQB6N4pn926IUUYZGzK" Jul 08 20:19:00 volumio volumio[876]: 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: 3 Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 20:19:00 volumio go-librespot[1187]: time="2025-07-08T20:19:00+02:00" level=trace msg="emitting websocket event: playing" Jul 08 20:19:00 volumio volumio[876]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:54KFQB6N4pn926IUUYZGzK","play_origin":""}} Jul 08 20:19:00 volumio volumio[876]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 20:19:00 volumio volumio[876]: TypeError: Cannot read property 'service' of undefined Jul 08 20:19:00 volumio volumio[876]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) Jul 08 20:19:00 volumio volumio[876]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) Jul 08 20:19:00 volumio volumio[876]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) Jul 08 20:19:00 volumio volumio[876]: at WebSocket.emit (events.js:315:20) Jul 08 20:19:00 volumio volumio[876]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jul 08 20:19:00 volumio volumio[876]: at Receiver.emit (events.js:315:20) Jul 08 20:19:00 volumio volumio[876]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jul 08 20:19:00 volumio volumio[876]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jul 08 20:19:00 volumio volumio[876]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jul 08 20:19:00 volumio volumio[876]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jul 08 20:19:00 volumio volumio[876]: at writeOrBuffer (internal/streams/writable.js:358:12) Jul 08 20:19:00 volumio volumio[876]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jul 08 20:19:00 volumio volumio[876]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jul 08 20:19:00 volumio volumio[876]: at Socket.emit (events.js:315:20) Jul 08 20:19:00 volumio volumio[876]: at addChunk (internal/streams/readable.js:309:12) Jul 08 20:19:00 volumio volumio[876]: at readableAddChunk (internal/streams/readable.js:284:9) Jul 08 20:19:00 volumio volumio[876]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 20:19:01 volumio sudo[1324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-08 20:18 Jul 08 20:19:01 volumio sudo[1324]: 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"