-- Logs begin at Fri 2025-04-04 04:53:42 CST, end at Thu 2025-05-08 17:30:09 CST. -- May 08 17:29:41 volumio-pm systemd-timedated[989]: Changed local time to Thu May 8 17:29:41 2025 May 08 17:29:41 volumio-pm sudo[987]: pam_unix(sudo:session): session closed for user root May 08 17:29:41 volumio-pm volumio-time-update[535]: volumio-time-update-util: System time updated successfully. May 08 17:29:41 volumio-pm systemd[1]: Started Volumio Time Update Utility. May 08 17:29:41 volumio-pm systemd[1]: Starting Daily apt download activities... May 08 17:29:42 volumio-pm systemd[1]: apt-daily.service: Succeeded. May 08 17:29:42 volumio-pm systemd[1]: Started Daily apt download activities. May 08 17:29:43 volumio-pm systemd[1]: Starting Daily apt upgrade and clean activities... May 08 17:29:43 volumio-pm nmbd[701]: [2025/05/08 17:29:43.069297, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 08 17:29:43 volumio-pm nmbd[701]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 08 17:29:43 volumio-pm systemd[1]: Started Samba NMB Daemon. May 08 17:29:43 volumio-pm systemd[1]: Starting Samba Winbind Daemon... May 08 17:29:43 volumio-pm sh[460]: timed out May 08 17:29:43 volumio-pm dhcpcd[494]: timed out May 08 17:29:43 volumio-pm winbindd[1044]: [2025/05/08 17:29:43.775798, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 08 17:29:43 volumio-pm sh[460]: dhcpcd exited May 08 17:29:43 volumio-pm winbindd[1044]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 08 17:29:43 volumio-pm sh[460]: ifup: failed to bring up eth0 May 08 17:29:43 volumio-pm dhcpcd[494]: dhcpcd exited May 08 17:29:43 volumio-pm systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 08 17:29:43 volumio-pm systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 08 17:29:43 volumio-pm winbindd[1044]: [2025/05/08 17:29:43.820661, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 08 17:29:43 volumio-pm systemd[1]: Started Samba Winbind Daemon. May 08 17:29:43 volumio-pm winbindd[1044]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 08 17:29:43 volumio-pm systemd[1]: Starting Samba SMB Daemon... May 08 17:29:44 volumio-pm volumio[965]: info: ------------------------------------------- May 08 17:29:44 volumio-pm volumio[965]: info: ----- Volumio3 ---- May 08 17:29:44 volumio-pm volumio[965]: info: ------------------------------------------- May 08 17:29:44 volumio-pm volumio[965]: info: ----- System startup ---- May 08 17:29:44 volumio-pm volumio[965]: info: ------------------------------------------- May 08 17:29:44 volumio-pm systemd[1]: apt-daily-upgrade.service: Succeeded. May 08 17:29:44 volumio-pm systemd[1]: Started Daily apt upgrade and clean activities. May 08 17:29:44 volumio-pm smbd[1084]: [2025/05/08 17:29:44.796540, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 08 17:29:44 volumio-pm smbd[1084]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 08 17:29:44 volumio-pm systemd[1]: Started Samba SMB Daemon. May 08 17:29:44 volumio-pm systemd[1]: Reached target Multi-User System. May 08 17:29:44 volumio-pm systemd[1]: Reached target Graphical Interface. May 08 17:29:44 volumio-pm systemd[1]: Starting Update UTMP about System Runlevel Changes... May 08 17:29:44 volumio-pm systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 08 17:29:44 volumio-pm systemd[1]: Started Update UTMP about System Runlevel Changes. May 08 17:29:44 volumio-pm systemd[1]: Startup finished in 15.763s (kernel) + 38.965s (userspace) = 54.729s. May 08 17:29:46 volumio-pm volumio[965]: info: MYVOLUMIO Environment detected May 08 17:29:46 volumio-pm volumio[965]: info: Plugin folders cleanup May 08 17:29:46 volumio-pm volumio[965]: info: Scanning into folder /volumio/app/plugins/ May 08 17:29:46 volumio-pm volumio[965]: info: Scanning category audio_interface May 08 17:29:46 volumio-pm volumio[965]: info: Scanning category miscellanea May 08 17:29:46 volumio-pm volumio[965]: info: Scanning category music_service May 08 17:29:46 volumio-pm volumio[965]: info: Scanning category plugins.json May 08 17:29:46 volumio-pm volumio[965]: info: Scanning category system_controller May 08 17:29:46 volumio-pm volumio[965]: info: Scanning category user_interface May 08 17:29:46 volumio-pm volumio[965]: info: Scanning into folder /data/plugins/ May 08 17:29:46 volumio-pm volumio[965]: info: Scanning category music_service May 08 17:29:46 volumio-pm volumio[965]: info: Plugin folders cleanup completed May 08 17:29:46 volumio-pm volumio[965]: info: ------------------------------------------- May 08 17:29:46 volumio-pm volumio[965]: info: ----- Core plugins startup ---- May 08 17:29:46 volumio-pm volumio[965]: info: ------------------------------------------- May 08 17:29:46 volumio-pm volumio[965]: info: Loading plugins from folder /volumio/app/plugins/ May 08 17:29:46 volumio-pm volumio[965]: info: Adding plugin upnp to MyMusic Plugins May 08 17:29:46 volumio-pm volumio[965]: info: Adding plugin airplay_emulation to MyMusic Plugins May 08 17:29:46 volumio-pm volumio[965]: info: Adding plugin upnp_browser to MyMusic Plugins May 08 17:29:46 volumio-pm volumio[965]: info: Loading plugins from folder /data/plugins/ May 08 17:29:46 volumio-pm volumio[965]: info: Loading plugin "system"... May 08 17:29:46 volumio-pm volumio[965]: info: Loading plugin "appearance"... May 08 17:29:47 volumio-pm systemd[1]: systemd-hostnamed.service: Succeeded. May 08 17:29:47 volumio-pm volumio-remote-updater[532]: [2025-05-08 17:29:47] [connect] Successful connection May 08 17:29:48 volumio-pm volumio[965]: info: Loading plugin "network"... May 08 17:29:48 volumio-pm volumio[965]: info: Refreshing Cached IP Addresses May 08 17:29:48 volumio-pm sudo[1123]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 08 17:29:48 volumio-pm sudo[1123]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:48 volumio-pm sudo[1123]: pam_unix(sudo:session): session closed for user root May 08 17:29:48 volumio-pm sudo[1125]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 08 17:29:48 volumio-pm sudo[1125]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:48 volumio-pm sudo[1125]: pam_unix(sudo:session): session closed for user root May 08 17:29:48 volumio-pm volumio[965]: info: Loading plugin "services"... May 08 17:29:48 volumio-pm volumio[965]: info: Loading plugin "alsa_controller"... May 08 17:29:48 volumio-pm sudo[1134]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 08 17:29:48 volumio-pm sudo[1134]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:48 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 08 17:29:48 volumio-pm volumio[965]: info: Loading plugin "wizard"... May 08 17:29:48 volumio-pm volumio[965]: info: Loading plugin "networkfs"... May 08 17:29:48 volumio-pm volumio[965]: info: Starting Udev Watcher for removable devices May 08 17:29:48 volumio-pm sudo[1151]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.10.40/Public /mnt/NAS/Public May 08 17:29:48 volumio-pm sudo[1151]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:48 volumio-pm volumio[965]: info: Ignoring mount for partition: boot May 08 17:29:48 volumio-pm volumio[965]: info: Ignoring mount for partition: volumio May 08 17:29:48 volumio-pm volumio[965]: info: Ignoring mount for partition: volumio_data May 08 17:29:48 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 08 17:29:48 volumio-pm volumio[965]: info: Loading plugin "volumio_command_line_client"... May 08 17:29:48 volumio-pm volumio[965]: info: Loading plugin "upnp"... May 08 17:29:49 volumio-pm volumio[965]: info: [1746746989008] Starting Upmpd Daemon May 08 17:29:49 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 08 17:29:49 volumio-pm volumio[965]: info: Loading plugin "my_music"... May 08 17:29:49 volumio-pm volumio[965]: info: Loading plugin "mpd"... May 08 17:29:49 volumio-pm kernel: Key type cifs.spnego registered May 08 17:29:49 volumio-pm kernel: Key type cifs.idmap registered May 08 17:29:49 volumio-pm 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. May 08 17:29:49 volumio-pm kernel: CIFS: Attempting to mount //192.168.10.40/Public May 08 17:29:49 volumio-pm kernel: cryptd: max_cpu_qlen set to 1000 May 08 17:29:49 volumio-pm volumio[965]: info: Loading plugin "upnp_browser"... May 08 17:29:50 volumio-pm volumio[965]: info: Loading plugin "alarm-clock"... May 08 17:29:50 volumio-pm volumio[965]: info: Loading plugin "airplay_emulation"... May 08 17:29:50 volumio-pm volumio[965]: info: Starting Shairport Sync May 08 17:29:50 volumio-pm volumio[965]: info: Loading plugin "last_100"... May 08 17:29:50 volumio-pm volumio[965]: info: Loading plugin "webradio"... May 08 17:29:51 volumio-pm volumio[965]: info: Loading plugin "i2s_dacs"... May 08 17:29:51 volumio-pm volumio[965]: info: I2S DAC not set, start Auto-detection May 08 17:29:51 volumio-pm volumio[965]: info: Loading plugin "volumiodiscovery"... May 08 17:29:51 volumio-pm volumio[965]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 08 17:29:51 volumio-pm volumio[965]: *** WARNING *** Please fix your application to use the native API of Avahi! May 08 17:29:51 volumio-pm volumio[965]: *** WARNING *** For more information see May 08 17:29:51 volumio-pm node[965]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 08 17:29:51 volumio-pm volumio[965]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 08 17:29:51 volumio-pm volumio[965]: *** WARNING *** Please fix your application to use the native API of Avahi! May 08 17:29:51 volumio-pm volumio[965]: *** WARNING *** For more information see May 08 17:29:51 volumio-pm node[965]: *** WARNING *** Please fix your application to use the native API of Avahi! May 08 17:29:51 volumio-pm node[965]: *** WARNING *** For more information see May 08 17:29:51 volumio-pm node[965]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 08 17:29:51 volumio-pm node[965]: *** WARNING *** Please fix your application to use the native API of Avahi! May 08 17:29:51 volumio-pm node[965]: *** WARNING *** For more information see May 08 17:29:51 volumio-pm volumio[965]: info: Applying required configuration parameters for plugin volumiodiscovery May 08 17:29:51 volumio-pm volumio[965]: info: Discovery: Started advertising with name: Volumio-PM May 08 17:29:51 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 08 17:29:51 volumio-pm volumio[965]: info: Loading plugin "spop"... May 08 17:29:52 volumio-pm sudo[1134]: pam_unix(sudo:session): session closed for user root May 08 17:29:53 volumio-pm volumio[965]: info: Loading plugin "outputs"... May 08 17:29:53 volumio-pm volumio[965]: info: Loading plugin "albumart"... May 08 17:29:53 volumio-pm volumio[965]: info: Plugin example_plugin is not enabled May 08 17:29:53 volumio-pm volumio[965]: info: Loading plugin "inputs"... May 08 17:29:53 volumio-pm volumio[965]: info: Loading plugin "updater_comm"... May 08 17:29:54 volumio-pm volumio[965]: info: Plugin mpdemulation is not enabled May 08 17:29:54 volumio-pm volumio[965]: info: Loading plugin "rest_api"... May 08 17:29:54 volumio-pm volumio[965]: info: Loading plugin "websocket"... May 08 17:29:54 volumio-pm volumio[965]: info: Starting Socket.io Server version 2.3.0 May 08 17:29:54 volumio-pm volumio[965]: info: Loading i18n strings for locale en May 08 17:29:54 volumio-pm volumio[965]: Updating browse sources language May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 08 17:29:54 volumio-pm volumio[965]: Forking 3 albumart workers May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::initPlayerControls May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: Express server listening on port 3000 May 08 17:29:54 volumio-pm volumio[965]: [Metrics] WebUI: 12s 577.88ms May 08 17:29:54 volumio-pm volumio[965]: info: CoreStateMachine::resetVolumioState May 08 17:29:54 volumio-pm volumio[965]: info: CoreStateMachine::getcurrentVolume May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::volumioRetrievevolume May 08 17:29:54 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 08 17:29:54 volumio-pm volumio[965]: info: Volumio Network Manager: Network status updated: 2 May 08 17:29:55 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 08 17:29:55 volumio-pm volumio[965]: info: Reloading queue from file May 08 17:29:55 volumio-pm volumio[965]: info: VolumeController:: Volume=88 Mute =false May 08 17:29:55 volumio-pm volumio[965]: info: CoreStateMachine::pushState May 08 17:29:55 volumio-pm volumio[965]: info: CorePlayQueue::getTrack 0 May 08 17:29:55 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 17:29:55 volumio-pm volumio[965]: info: CoreCommandRouter::volumioPushState May 08 17:29:55 volumio-pm volumio[965]: info: CoreStateMachine::updateTrackBlock May 08 17:29:55 volumio-pm volumio[965]: info: CorePlayQueue::getTrackBlock May 08 17:29:55 volumio-pm volumio[965]: info: CoreCommandRouter::volumioRetrievevolume May 08 17:29:55 volumio-pm volumio[965]: info: Setting Device type: Raspberry PI May 08 17:29:55 volumio-pm volumio[965]: info: CoreStateMachine::setRepeat null single undefined May 08 17:29:55 volumio-pm volumio[965]: info: CoreStateMachine::pushState May 08 17:29:55 volumio-pm volumio[965]: info: CorePlayQueue::getTrack 0 May 08 17:29:55 volumio-pm volumio[965]: info: CoreCommandRouter::volumioPushState May 08 17:29:55 volumio-pm volumio[965]: info: CoreStateMachine::setRandom null May 08 17:29:55 volumio-pm volumio[965]: info: CoreStateMachine::pushState May 08 17:29:55 volumio-pm volumio[965]: info: CorePlayQueue::getTrack 0 May 08 17:29:55 volumio-pm volumio[965]: info: CoreCommandRouter::volumioPushState May 08 17:29:55 volumio-pm volumio[965]: info: Discovery: adding c76ddcd0-cf11-4b49-a5f0-90ee7466ced5 May 08 17:29:55 volumio-pm volumio[965]: info: Discovery: Found device Volumio-PM May 08 17:29:55 volumio-pm volumio[965]: info: CoreCommandRouter::volumioGetState May 08 17:29:55 volumio-pm volumio[965]: info: CorePlayQueue::getTrack 0 May 08 17:29:55 volumio-pm volumio[965]: info: VolumeController:: Volume=88 Mute =false May 08 17:29:55 volumio-pm volumio[965]: info: CoreStateMachine::pushState May 08 17:29:55 volumio-pm volumio[965]: info: CorePlayQueue::getTrack 0 May 08 17:29:55 volumio-pm volumio[965]: info: CoreCommandRouter::volumioPushState May 08 17:29:55 volumio-pm volumio[965]: Starting albumart workers May 08 17:29:55 volumio-pm volumio[965]: Starting albumart workers May 08 17:29:55 volumio-pm volumio[965]: Starting albumart workers May 08 17:29:57 volumio-pm sudo[1151]: pam_unix(sudo:session): session closed for user root May 08 17:29:57 volumio-pm volumio[965]: info: Completed loading Core Plugins May 08 17:29:57 volumio-pm volumio[965]: info: Preparing to generate the ALSA configuration file May 08 17:29:57 volumio-pm volumio[965]: info: Asound.conf file unchanged, so no further update is needed May 08 17:29:57 volumio-pm volumio[965]: info: Output device has changed, restarting MPD May 08 17:29:57 volumio-pm volumio[965]: info: Output device has changed, restarting Shairport Sync May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 08 17:29:57 volumio-pm sudo[1256]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 08 17:29:57 volumio-pm sudo[1256]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:57 volumio-pm sudo[1256]: pam_unix(sudo:session): session closed for user root May 08 17:29:57 volumio-pm sudo[1258]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 08 17:29:57 volumio-pm sudo[1258]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:57 volumio-pm systemd[1]: Stopping Music Player Daemon... May 08 17:29:57 volumio-pm volumio[965]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 08 17:29:57 volumio-pm volumio[965]: info: ___________ START PLUGINS ___________ May 08 17:29:57 volumio-pm volumio[965]: info: ControllerMpd::onStart: Initializing MPD May 08 17:29:57 volumio-pm volumio[965]: info: Creating MPD Configuration file May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 08 17:29:57 volumio-pm sudo[1265]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 08 17:29:57 volumio-pm volumio[965]: info: [1746746997647] CoreMusicLibrary::Adding element Media Servers May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 08 17:29:57 volumio-pm sudo[1265]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:57 volumio-pm sudo[1265]: pam_unix(sudo:session): session closed for user root May 08 17:29:57 volumio-pm sudo[1267]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 08 17:29:57 volumio-pm sudo[1267]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 08 17:29:57 volumio-pm volumio[965]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 08 17:29:57 volumio-pm systemd[1]: mpd.service: Succeeded. May 08 17:29:57 volumio-pm systemd[1]: Stopped Music Player Daemon. May 08 17:29:57 volumio-pm volumio[965]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 08 17:29:57 volumio-pm volumio[965]: info: [1746746997925] CoreMusicLibrary::Adding element Last_100 May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 08 17:29:57 volumio-pm volumio[965]: info: [1746746997932] CoreMusicLibrary::Adding element Webradio May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 08 17:29:57 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 08 17:29:57 volumio-pm volumio[965]: info: Initializing BBC Radios May 08 17:29:57 volumio-pm systemd[1]: Starting Music Player Daemon... May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: Creating Spotify config file May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: Volumio Calling Home May 08 17:29:58 volumio-pm sudo[1274]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 08 17:29:58 volumio-pm sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:58 volumio-pm sudo[1274]: pam_unix(sudo:session): session closed for user root May 08 17:29:58 volumio-pm volumio[965]: info: MPD Permissions set May 08 17:29:58 volumio-pm volumio[965]: info: MPD Permissions set May 08 17:29:58 volumio-pm volumio[965]: info: Spotify config file written May 08 17:29:58 volumio-pm sudo[1293]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 08 17:29:58 volumio-pm sudo[1293]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:58 volumio-pm volumio[965]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm systemd[1]: Started go-librespot Daemon. May 08 17:29:58 volumio-pm go-librespot[1300]: go-librespot daemon starting... May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm sudo[1293]: pam_unix(sudo:session): session closed for user root May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 17:29:58 volumio-pm volumio[965]: info: No need to fix Spotify hosts May 08 17:29:59 volumio-pm sudo[1326]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 08 17:29:59 volumio-pm sudo[1326]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:59 volumio-pm sudo[1326]: pam_unix(sudo:session): session closed for user root May 08 17:29:59 volumio-pm sudo[1328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 08 17:29:59 volumio-pm sudo[1328]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:59 volumio-pm sudo[1328]: pam_unix(sudo:session): session closed for user root May 08 17:29:59 volumio-pm volumio[965]: info: Volumio called home May 08 17:29:59 volumio-pm volumio[965]: info: Starting Shairport Sync May 08 17:29:59 volumio-pm volumio[965]: info: Starting Shairport Sync May 08 17:29:59 volumio-pm volumio[965]: info: Starting Shairport Sync May 08 17:29:59 volumio-pm sudo[1332]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 08 17:29:59 volumio-pm sudo[1332]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:59 volumio-pm sudo[1334]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 08 17:29:59 volumio-pm sudo[1334]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:59 volumio-pm volumio[965]: info: CoreCommandRouter::volumioGetState May 08 17:29:59 volumio-pm volumio[965]: info: CorePlayQueue::getTrack 0 May 08 17:29:59 volumio-pm sudo[1338]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 08 17:29:59 volumio-pm sudo[1338]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:59 volumio-pm systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 08 17:29:59 volumio-pm systemd[1]: shairport-sync.service: Succeeded. May 08 17:29:59 volumio-pm systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 08 17:29:59 volumio-pm go-librespot[1300]: time="2025-05-08T17:29:59-06:00" level=info msg="running go-librespot 0.2.0" May 08 17:29:59 volumio-pm go-librespot[1300]: time="2025-05-08T17:29:59-06:00" level=debug msg="app state loaded" May 08 17:29:59 volumio-pm go-librespot[1300]: time="2025-05-08T17:29:59-06:00" level=debug msg="stored credentials not found" May 08 17:29:59 volumio-pm go-librespot[1300]: time="2025-05-08T17:29:59-06:00" level=info msg="api server listening on 127.0.0.1:9879" May 08 17:29:59 volumio-pm systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 08 17:29:59 volumio-pm sudo[1332]: pam_unix(sudo:session): session closed for user root May 08 17:29:59 volumio-pm sudo[1334]: pam_unix(sudo:session): session closed for user root May 08 17:29:59 volumio-pm systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 08 17:29:59 volumio-pm systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 08 17:29:59 volumio-pm systemd[1]: shairport-sync.service: Succeeded. May 08 17:29:59 volumio-pm systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 08 17:29:59 volumio-pm systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 08 17:29:59 volumio-pm sudo[1338]: pam_unix(sudo:session): session closed for user root May 08 17:29:59 volumio-pm volumio[965]: info: Shairport-Sync Started May 08 17:29:59 volumio-pm volumio[965]: Error adding Membership: Error: addMembership EINVAL May 08 17:29:59 volumio-pm volumio[965]: info: Shairport-Sync Started May 08 17:29:59 volumio-pm volumio[965]: info: Shairport-Sync Started May 08 17:29:59 volumio-pm sudo[1343]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 08 17:29:59 volumio-pm sudo[1343]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 17:29:59 volumio-pm systemd[1]: Started UPnP Renderer front-end to MPD. May 08 17:29:59 volumio-pm sudo[1343]: pam_unix(sudo:session): session closed for user root May 08 17:29:59 volumio-pm volumio[965]: info: Upmpdcli Daemon Started May 08 17:30:00 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:00-06:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 08 17:30:00 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:00-06:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 08 17:30:00 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:00-06:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 08 17:30:00 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:00-06:00" level=info msg="zeroconf server listening on port 44491" May 08 17:30:01 volumio-pm mpd[1291]: May 08 17:30 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 08 17:30:01 volumio-pm systemd[1]: Started Music Player Daemon. May 08 17:30:01 volumio-pm sudo[1258]: pam_unix(sudo:session): session closed for user root May 08 17:30:01 volumio-pm sudo[1267]: pam_unix(sudo:session): session closed for user root May 08 17:30:01 volumio-pm volumio[965]: info: Completed starting Core Plugins May 08 17:30:01 volumio-pm volumio[965]: info: ------------------------------------------- May 08 17:30:01 volumio-pm volumio[965]: info: ----- MyVolumio plugins startup ---- May 08 17:30:01 volumio-pm volumio[965]: info: ------------------------------------------- May 08 17:30:01 volumio-pm volumio[965]: info: [MyVolumio PluginManager] Fetching plans data.... May 08 17:30:01 volumio-pm volumio[965]: error: MPD error: The expression evaluated to a falsy value: May 08 17:30:01 volumio-pm volumio[965]: assert.ok(self.idling) May 08 17:30:01 volumio-pm volumio[965]: error: The expression evaluated to a falsy value: May 08 17:30:01 volumio-pm volumio[965]: assert.ok(self.idling) May 08 17:30:01 volumio-pm volumio[965]: info: MPD running with PID1291 May 08 17:30:01 volumio-pm volumio[965]: ,establishing connection May 08 17:30:01 volumio-pm volumio[965]: error: updateQueue error: null May 08 17:30:01 volumio-pm volumio[965]: error: updateQueue error: null May 08 17:30:01 volumio-pm volumio[1347]: Generating RSA private key, 4096 bit long modulus (2 primes) May 08 17:30:02 volumio-pm volumio[965]: info: go-librespot daemon successfully initialized May 08 17:30:02 volumio-pm volumio-remote-updater[532]: [2025-05-08 17:30:02] [connect] Successful connection May 08 17:30:02 volumio-pm volumio-remote-updater[532]: [2025-05-08 17:30:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1746747002 101 May 08 17:30:02 volumio-pm volumio[965]: 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 May 08 17:30:02 volumio-pm volumio[1347]: ..++++ May 08 17:30:04 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:04-06:00" level=debug msg="obtained new client token: AAAb0rd24rHYIWl1HSpENXlhvT0QAOZUbHDVcBWgKwG8X0B+q1MmzyoE6IpglJLSbo6rflYtUhG7XDFEjB/4zBu2tt0BY+UVkXzzy8vwhAuualw3kvUOhXfU27lp1QzTkHXnBl8LtgGS6AotCpUsFmYN9FnhN8pmEpqecg4Um6ceTdx+yDUPGrBkVc4CrcYEBur1ESjj0dbs2azkdYFsGsriHrB5HLkdXlA58RH7EnnJ6hIUDNCvlm+U" May 08 17:30:04 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:04-06:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" May 08 17:30:04 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:04-06:00" level=debug msg="connected to ap-gue1.spotify.com:443" May 08 17:30:04 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:04-06:00" level=debug msg="completed keyexchange" May 08 17:30:04 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:04-06:00" level=debug msg="completed challenge" May 08 17:30:04 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:04-06:00" level=info msg="authenticated AP as chavodelvocho" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=info msg="authenticated Login5 as chavodelvocho" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=info msg="accepted zeroconf user chavodelvocho from iPhone" May 08 17:30:05 volumio-pm volumio[965]: info: Initializing connection to go-librespot Websocket May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="new websocket client" May 08 17:30:05 volumio-pm volumio[965]: info: Connection to go-librespot Websocket established May 08 17:30:05 volumio-pm volumio[965]: info: CoreCommandRouter::volumioGetState May 08 17:30:05 volumio-pm volumio[965]: info: CorePlayQueue::getTrack 0 May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="dealer connection opened" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=trace msg="starting accesspoint recv loop" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=trace msg="starting dealer recv loop" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=trace msg="received accesspoint ping" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="received connection id: YmE3NTgwNzktMTg2Yi00OWU3LTkzMDgtZDczYThhYTY1MjFkK2RlYWxlcit0Y3A6Ly8wYWNiZmIwNi5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArMTdDNzYwNjQwRjM4RTQwQjY5NUEzOEUwREY4MTFCRjEwNDE2MTE4QjdBRUVBNjgxM0FFOUM2NjBFQjEyMEQwRQ==" May 08 17:30:05 volumio-pm volumio[965]: info: Listing playlists May 08 17:30:05 volumio-pm volumio[965]: info: Listing playlists May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="put connect state because NEW_DEVICE" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 08 17:30:05 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:05-06:00" level=trace msg="received accesspoint pong ack" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="handling transfer player command from 9cecfcd7e169e5aa218a21e0e80f921fc51d34f3" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="resolved context of track" uri="spotify:playlist:0aIQWnC6X9WwGz1zuEv94F" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=trace msg="fetched new page 0 with 49 items (list: 49)" uri="spotify:playlist:0aIQWnC6X9WwGz1zuEv94F" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="loading track (paused: false, position: 218721ms)" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=trace msg="emitting websocket event: will_play" May 08 17:30:06 volumio-pm volumio[965]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5wV0djVlMGBH3gpW7Iap1K","play_origin":"playlist/ondemand"}} May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="selected format OGG_VORBIS_320 (bb8d0e600f870fabfe65339b9737613d17120842)" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="requested aes key for file bb8d0e600f870fabfe65339b9737613d17120842, gid: 5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3181" May 08 17:30:06 volumio-pm volumio[965]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 08 17:30:06 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:06-06:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2036" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=debug msg="fetched first chunk of 20, total size is 9991964 bytes" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=debug msg="fetched chunk 19/19, size: 30492" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=debug msg="fetched chunk 18/19, size: 524288" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=debug msg="fetched chunk 17/19, size: 524288" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=trace msg="seek to 218721ms (diff: 71ms, samples: 9645596, bytes: 9305793)" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=debug msg="created new output device" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06: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" May 08 17:30:07 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:07-06:00" level=info msg="loaded track \"Pa Romper la Rutina\" (paused: false, position: 218721ms, duration: 235146ms, prefetched: false)" uri="spotify:track:5wV0djVlMGBH3gpW7Iap1K" May 08 17:30:07 volumio-pm volumio[965]: Cannot compose Albumart path May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=trace msg="emitting websocket event: metadata" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="prefetching next track" uri="spotify:track:7FTzm3pKm2hukhfNF8XHq5" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=trace msg="emitting websocket event: active" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="sending successful reply for dealer request" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="selected format OGG_VORBIS_320 (13c52677ff58d417799f325c70fb76f41b726cb6)" uri="spotify:track:7FTzm3pKm2hukhfNF8XHq5" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="requested aes key for file 13c52677ff58d417799f325c70fb76f41b726cb6, gid: 7FTzm3pKm2hukhfNF8XHq5" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=trace msg="emitting websocket event: playing" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="fetched first chunk of 27, total size is 14137456 bytes" uri="spotify:track:7FTzm3pKm2hukhfNF8XHq5" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=info msg="prefetched track \"Ya No\" (duration: 323837ms)" uri="spotify:track:7FTzm3pKm2hukhfNF8XHq5" May 08 17:30:08 volumio-pm volumio[965]: info: Getting Spotify volume May 08 17:30:08 volumio-pm volumio[965]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5wV0djVlMGBH3gpW7Iap1K","name":"Pa Romper la Rutina","artist_names":["Cocofunka"],"album_name":"Hacer Ecoo","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029de0a7f9d5d064da314f71ab","position":218721,"duration":235146,"release_date":"year:2012 month:5 day:14","track_number":4,"disc_number":1}} May 08 17:30:08 volumio-pm volumio[965]: SPOTIFY: received: {"type":"active","data":null} May 08 17:30:08 volumio-pm volumio[965]: info: Aligning Spotify Volume to Volumio Volume May 08 17:30:08 volumio-pm volumio[965]: info: CoreCommandRouter::volumioGetState May 08 17:30:08 volumio-pm volumio[965]: info: CorePlayQueue::getTrack 0 May 08 17:30:08 volumio-pm volumio[965]: info: Setting Spotify Volume from Volumio: 88 May 08 17:30:08 volumio-pm volumio[965]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5wV0djVlMGBH3gpW7Iap1K","play_origin":"playlist/ondemand"}} May 08 17:30:08 volumio-pm volumio[965]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 08 17:30:08 volumio-pm volumio[965]: TypeError: Cannot read property 'service' of undefined May 08 17:30:08 volumio-pm volumio[965]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) May 08 17:30:08 volumio-pm volumio[965]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) May 08 17:30:08 volumio-pm volumio[965]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) May 08 17:30:08 volumio-pm volumio[965]: at WebSocket.emit (events.js:315:20) May 08 17:30:08 volumio-pm volumio[965]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 08 17:30:08 volumio-pm volumio[965]: at Receiver.emit (events.js:315:20) May 08 17:30:08 volumio-pm volumio[965]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 08 17:30:08 volumio-pm volumio[965]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 08 17:30:08 volumio-pm volumio[965]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 08 17:30:08 volumio-pm volumio[965]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 08 17:30:08 volumio-pm volumio[965]: at writeOrBuffer (internal/streams/writable.js:358:12) May 08 17:30:08 volumio-pm volumio[965]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 08 17:30:08 volumio-pm volumio[965]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 08 17:30:08 volumio-pm volumio[965]: at Socket.emit (events.js:315:20) May 08 17:30:08 volumio-pm volumio[965]: at addChunk (internal/streams/readable.js:309:12) May 08 17:30:08 volumio-pm volumio[965]: at readableAddChunk (internal/streams/readable.js:284:9) May 08 17:30:08 volumio-pm volumio[965]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="fetched chunk 3/26, size: 524288" uri="spotify:track:7FTzm3pKm2hukhfNF8XHq5" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="fetched chunk 2/26, size: 524288" uri="spotify:track:7FTzm3pKm2hukhfNF8XHq5" May 08 17:30:08 volumio-pm go-librespot[1300]: time="2025-05-08T17:30:08-06:00" level=debug msg="fetched chunk 1/26, size: 524288" uri="spotify:track:7FTzm3pKm2hukhfNF8XHq5" May 08 17:30:09 volumio-pm sudo[1395]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-08 17:29 May 08 17:30:09 volumio-pm sudo[1395]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"