-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Mon 2025-05-26 22:48:22 CEST. -- May 26 22:47:57 hifi systemd-timedated[984]: Changed local time to Mon May 26 22:47:57 2025 May 26 22:47:57 hifi systemd[1]: Starting Daily apt download activities... May 26 22:47:57 hifi sudo[982]: pam_unix(sudo:session): session closed for user root May 26 22:47:57 hifi volumio-cpu-tweak[995]: Setting RT Priority for mpd May 26 22:47:57 hifi volumio-time-update[600]: volumio-time-update-util: System time updated successfully. May 26 22:47:57 hifi systemd[1]: Started Volumio Time Update Utility. May 26 22:47:57 hifi volumio-cpu-tweak[995]: Setting MPD Affinity May 26 22:47:57 hifi volumio-cpu-tweak[995]: pid 786's current affinity mask: f May 26 22:47:57 hifi volumio-cpu-tweak[995]: pid 786's new affinity mask: 3 May 26 22:47:57 hifi volumio-cpu-tweak[995]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input May 26 22:47:57 hifi volumio-cpu-tweak[995]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance May 26 22:47:57 hifi systemd[1]: volumio_cpu_tweak.service: Succeeded. May 26 22:47:57 hifi ntpd[771]: Listen normally on 3 wlan0 192.168.1.121:123 May 26 22:47:57 hifi ntpd[771]: new interface(s) found: waking up resolver May 26 22:47:58 hifi systemd[1]: apt-daily.service: Succeeded. May 26 22:47:58 hifi systemd[1]: Started Daily apt download activities. May 26 22:47:58 hifi systemd[1]: Starting Daily apt upgrade and clean activities... May 26 22:47:58 hifi nmbd[714]: [2025/05/26 22:47:58.232051, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 22:47:58 hifi systemd[1]: Started Samba NMB Daemon. May 26 22:47:58 hifi nmbd[714]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 26 22:47:58 hifi systemd[1]: Starting Samba Winbind Daemon... May 26 22:47:58 hifi winbindd[1073]: [2025/05/26 22:47:58.665681, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 26 22:47:58 hifi winbindd[1073]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 26 22:47:58 hifi winbindd[1073]: [2025/05/26 22:47:58.729303, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 22:47:58 hifi systemd[1]: Started Samba Winbind Daemon. May 26 22:47:58 hifi winbindd[1073]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 26 22:47:58 hifi volumio-remote-updater[595]: [2025-05-26 22:47:58] [info] asio async_connect error: system:111 (Connection refused) May 26 22:47:58 hifi volumio-remote-updater[595]: [2025-05-26 22:47:58] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 26 22:47:58 hifi volumio-remote-updater[595]: [2025-05-26 22:47:58] [error] handle_connect error: Underlying Transport Error May 26 22:47:58 hifi systemd[1]: Starting Samba SMB Daemon... May 26 22:47:58 hifi systemd[1]: apt-daily-upgrade.service: Succeeded. May 26 22:47:58 hifi systemd[1]: Started Daily apt upgrade and clean activities. May 26 22:47:59 hifi smbd[1113]: [2025/05/26 22:47:59.444323, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 22:47:59 hifi smbd[1113]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 26 22:47:59 hifi systemd[1]: Started Samba SMB Daemon. May 26 22:47:59 hifi systemd[1]: Reached target Multi-User System. May 26 22:47:59 hifi systemd[1]: Reached target Graphical Interface. May 26 22:47:59 hifi systemd[1]: Starting Update UTMP about System Runlevel Changes... May 26 22:47:59 hifi systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 26 22:47:59 hifi systemd[1]: Started Update UTMP about System Runlevel Changes. May 26 22:47:59 hifi systemd[1]: Startup finished in 13.372s (kernel) + 28.539s (userspace) = 41.912s. May 26 22:48:00 hifi volumio[994]: info: ------------------------------------------- May 26 22:48:00 hifi volumio[994]: info: ----- Volumio3 ---- May 26 22:48:00 hifi volumio[994]: info: ------------------------------------------- May 26 22:48:00 hifi volumio[994]: info: ----- System startup ---- May 26 22:48:00 hifi volumio[994]: info: ------------------------------------------- May 26 22:48:01 hifi volumio[994]: info: MYVOLUMIO Environment detected May 26 22:48:01 hifi volumio[994]: info: Plugin folders cleanup May 26 22:48:01 hifi volumio[994]: info: Scanning into folder /volumio/app/plugins/ May 26 22:48:01 hifi volumio[994]: info: Scanning category audio_interface May 26 22:48:01 hifi volumio[994]: info: Scanning category miscellanea May 26 22:48:01 hifi volumio[994]: info: Scanning category music_service May 26 22:48:01 hifi volumio[994]: info: Scanning category plugins.json May 26 22:48:01 hifi volumio[994]: info: Scanning category system_controller May 26 22:48:01 hifi volumio[994]: info: Scanning category user_interface May 26 22:48:01 hifi volumio[994]: info: Scanning into folder /data/plugins/ May 26 22:48:01 hifi volumio[994]: info: Scanning category music_service May 26 22:48:01 hifi volumio[994]: info: Plugin folders cleanup completed May 26 22:48:01 hifi volumio[994]: info: ------------------------------------------- May 26 22:48:01 hifi volumio[994]: info: ----- Core plugins startup ---- May 26 22:48:01 hifi volumio[994]: info: ------------------------------------------- May 26 22:48:01 hifi volumio[994]: info: Loading plugins from folder /volumio/app/plugins/ May 26 22:48:01 hifi volumio[994]: info: Adding plugin upnp to MyMusic Plugins May 26 22:48:01 hifi volumio[994]: info: Adding plugin airplay_emulation to MyMusic Plugins May 26 22:48:01 hifi volumio[994]: info: Adding plugin upnp_browser to MyMusic Plugins May 26 22:48:01 hifi volumio[994]: info: Loading plugins from folder /data/plugins/ May 26 22:48:01 hifi volumio[994]: info: Loading plugin "system"... May 26 22:48:01 hifi volumio[994]: info: Loading plugin "appearance"... May 26 22:48:03 hifi volumio[994]: info: Loading plugin "network"... May 26 22:48:03 hifi volumio[994]: info: Refreshing Cached IP Addresses May 26 22:48:03 hifi sudo[1139]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 26 22:48:03 hifi sudo[1139]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:03 hifi sudo[1139]: pam_unix(sudo:session): session closed for user root May 26 22:48:03 hifi sudo[1141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 26 22:48:03 hifi sudo[1141]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:03 hifi sudo[1141]: pam_unix(sudo:session): session closed for user root May 26 22:48:03 hifi volumio[994]: info: Loading plugin "services"... May 26 22:48:03 hifi volumio[994]: info: Loading plugin "alsa_controller"... May 26 22:48:03 hifi sudo[1151]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 26 22:48:03 hifi sudo[1151]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:03 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 22:48:03 hifi volumio[994]: info: Loading plugin "wizard"... May 26 22:48:03 hifi volumio[994]: info: Loading plugin "networkfs"... May 26 22:48:03 hifi volumio[994]: info: Starting Udev Watcher for removable devices May 26 22:48:03 hifi volumio[994]: info: Ignoring mount for partition: boot May 26 22:48:03 hifi volumio[994]: info: Ignoring mount for partition: volumio May 26 22:48:03 hifi volumio[994]: info: Ignoring mount for partition: volumio_data May 26 22:48:03 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 26 22:48:03 hifi volumio[994]: info: Loading plugin "volumio_command_line_client"... May 26 22:48:03 hifi volumio[994]: info: Plugin upnp is not enabled May 26 22:48:03 hifi volumio[994]: info: Loading plugin "my_music"... May 26 22:48:03 hifi volumio[994]: info: Loading plugin "mpd"... May 26 22:48:03 hifi systemd[1]: systemd-fsckd.service: Succeeded. May 26 22:48:03 hifi volumio[994]: info: Plugin upnp_browser is not enabled May 26 22:48:03 hifi volumio[994]: info: Loading plugin "alarm-clock"... May 26 22:48:04 hifi volumio[994]: info: Plugin airplay_emulation is not enabled May 26 22:48:04 hifi volumio[994]: info: Loading plugin "last_100"... May 26 22:48:04 hifi volumio[994]: info: Loading plugin "webradio"... May 26 22:48:04 hifi volumio[994]: info: Loading plugin "i2s_dacs"... May 26 22:48:04 hifi volumio[994]: info: Loading plugin "volumiodiscovery"... May 26 22:48:04 hifi volumio[994]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 26 22:48:04 hifi volumio[994]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 22:48:04 hifi volumio[994]: *** WARNING *** For more information see May 26 22:48:04 hifi volumio[994]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 26 22:48:04 hifi node[994]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 26 22:48:04 hifi volumio[994]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 22:48:04 hifi volumio[994]: *** WARNING *** For more information see May 26 22:48:04 hifi node[994]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 22:48:04 hifi node[994]: *** WARNING *** For more information see May 26 22:48:04 hifi node[994]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 26 22:48:04 hifi node[994]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 22:48:04 hifi node[994]: *** WARNING *** For more information see May 26 22:48:04 hifi volumio[994]: info: Applying required configuration parameters for plugin volumiodiscovery May 26 22:48:04 hifi volumio[994]: info: Discovery: Started advertising with name: Hifi May 26 22:48:04 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 26 22:48:04 hifi volumio[994]: info: Loading plugin "spop"... May 26 22:48:05 hifi sh[496]: timed out May 26 22:48:05 hifi dhcpcd[544]: timed out May 26 22:48:05 hifi sh[496]: dhcpcd exited May 26 22:48:05 hifi dhcpcd[544]: dhcpcd exited May 26 22:48:05 hifi sh[496]: ifup: failed to bring up eth0 May 26 22:48:05 hifi systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 26 22:48:05 hifi systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 26 22:48:06 hifi volumio[994]: info: Loading plugin "ytcr"... May 26 22:48:06 hifi sudo[1151]: pam_unix(sudo:session): session closed for user root May 26 22:48:07 hifi systemd[1]: systemd-hostnamed.service: Succeeded. May 26 22:48:08 hifi volumio-remote-updater[595]: [2025-05-26 22:48:08] [connect] Successful connection May 26 22:48:09 hifi volumio[994]: info: Loading plugin "outputs"... May 26 22:48:09 hifi volumio[994]: info: Loading plugin "albumart"... May 26 22:48:09 hifi volumio[994]: info: Plugin example_plugin is not enabled May 26 22:48:09 hifi volumio[994]: info: Loading plugin "inputs"... May 26 22:48:09 hifi volumio[994]: info: Loading plugin "updater_comm"... May 26 22:48:09 hifi volumio[994]: info: Plugin mpdemulation is not enabled May 26 22:48:09 hifi volumio[994]: info: Loading plugin "rest_api"... May 26 22:48:09 hifi volumio[994]: info: Loading plugin "websocket"... May 26 22:48:09 hifi volumio[994]: info: Starting Socket.io Server version 2.3.0 May 26 22:48:09 hifi volumio[994]: info: Loading i18n strings for locale fr May 26 22:48:09 hifi volumio[994]: Updating browse sources language May 26 22:48:09 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:48:09 hifi volumio[994]: Forking 3 albumart workers May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::initPlayerControls May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 26 22:48:10 hifi volumio[994]: Express server listening on port 3000 May 26 22:48:10 hifi volumio[994]: [Metrics] WebUI: 11s 274.50ms May 26 22:48:10 hifi volumio[994]: info: CoreStateMachine::resetVolumioState May 26 22:48:10 hifi volumio[994]: info: CoreStateMachine::getcurrentVolume May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::volumioRetrievevolume May 26 22:48:10 hifi volumio[994]: info: Volumio Network Manager: Network status updated: 2 May 26 22:48:10 hifi volumio-remote-updater[595]: [2025-05-26 22:48:10] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748292488 101 May 26 22:48:10 hifi volumio[994]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:48:10 hifi volumio[994]: info: Reloading queue from file May 26 22:48:10 hifi volumio[994]: info: CoreStateMachine::setRepeat null single undefined May 26 22:48:10 hifi volumio[994]: info: CoreStateMachine::pushState May 26 22:48:10 hifi volumio[994]: info: CorePlayQueue::getTrack 0 May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::volumioPushState May 26 22:48:10 hifi volumio[994]: info: CoreStateMachine::setRandom null May 26 22:48:10 hifi volumio[994]: info: CoreStateMachine::pushState May 26 22:48:10 hifi volumio[994]: info: CorePlayQueue::getTrack 0 May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::volumioPushState May 26 22:48:10 hifi volumio[994]: info: Setting Device type: Raspberry PI May 26 22:48:10 hifi volumio[994]: info: Completed loading Core Plugins May 26 22:48:10 hifi volumio[994]: info: Preparing to generate the ALSA configuration file May 26 22:48:10 hifi volumio[994]: info: VolumeController:: Volume=41 Mute =false May 26 22:48:10 hifi volumio[994]: info: CoreStateMachine::pushState May 26 22:48:10 hifi volumio[994]: info: CorePlayQueue::getTrack 0 May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::volumioPushState May 26 22:48:10 hifi volumio[994]: info: CoreStateMachine::updateTrackBlock May 26 22:48:10 hifi volumio[994]: info: CorePlayQueue::getTrackBlock May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::volumioRetrievevolume May 26 22:48:10 hifi volumio[994]: info: Asound.conf file unchanged, so no further update is needed May 26 22:48:10 hifi volumio[994]: info: Output device has changed, restarting MPD May 26 22:48:10 hifi volumio[994]: info: ___________ START PLUGINS ___________ May 26 22:48:10 hifi sudo[1212]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 26 22:48:10 hifi sudo[1212]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:10 hifi volumio[994]: info: ControllerMpd::onStart: Initializing MPD May 26 22:48:10 hifi volumio[994]: info: Creating MPD Configuration file May 26 22:48:10 hifi sudo[1212]: pam_unix(sudo:session): session closed for user root May 26 22:48:10 hifi sudo[1214]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 26 22:48:10 hifi sudo[1214]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 22:48:10 hifi volumio[994]: info: [1748292490892] CoreMusicLibrary::Adding element Last_100 May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:48:10 hifi sudo[1217]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 26 22:48:10 hifi sudo[1217]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 22:48:10 hifi volumio[994]: info: [1748292490913] CoreMusicLibrary::Adding element Webradio May 26 22:48:10 hifi systemd[1]: Stopping Music Player Daemon... May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:48:10 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 22:48:10 hifi volumio[994]: info: Initializing BBC Radios May 26 22:48:10 hifi sudo[1217]: pam_unix(sudo:session): session closed for user root May 26 22:48:10 hifi volumio[994]: Starting albumart workers May 26 22:48:10 hifi sudo[1221]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 26 22:48:10 hifi sudo[1221]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:10 hifi volumio[994]: Starting albumart workers May 26 22:48:11 hifi volumio[994]: Starting albumart workers May 26 22:48:12 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 22:48:12 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:48:12 hifi volumio[994]: info: Creating Spotify config file May 26 22:48:12 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:12 hifi systemd[1]: mpd.service: Succeeded. May 26 22:48:12 hifi systemd[1]: Stopped Music Player Daemon. May 26 22:48:12 hifi systemd[1]: Starting Music Player Daemon... May 26 22:48:12 hifi volumio[994]: info: Volumio Calling Home May 26 22:48:13 hifi sudo[1257]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 26 22:48:13 hifi sudo[1257]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:13 hifi sudo[1257]: pam_unix(sudo:session): session closed for user root May 26 22:48:13 hifi volumio[994]: info: Discovery: adding 364307eb-d49f-4bf1-9a6a-1b12c7a3803e May 26 22:48:13 hifi volumio[994]: info: Discovery: Found device Hifi May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::volumioGetState May 26 22:48:13 hifi volumio[994]: info: CorePlayQueue::getTrack 0 May 26 22:48:13 hifi volumio[994]: info: MPD Permissions set May 26 22:48:13 hifi volumio[994]: info: MPD Permissions set May 26 22:48:13 hifi volumio[994]: info: Volumio called home May 26 22:48:13 hifi volumio[994]: info: Spotify config file written May 26 22:48:13 hifi sudo[1276]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 26 22:48:13 hifi sudo[1276]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:48:13 hifi volumio[994]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi systemd[1]: Started go-librespot Daemon. May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:48:13 hifi go-librespot[1282]: Librespot-go daemon starting... May 26 22:48:13 hifi sudo[1276]: pam_unix(sudo:session): session closed for user root May 26 22:48:13 hifi volumio[994]: info: VolumeController:: Volume=41 Mute =false May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::volumioGetState May 26 22:48:13 hifi volumio[994]: info: CorePlayQueue::getTrack 0 May 26 22:48:13 hifi volumio[994]: info: CoreStateMachine::pushState May 26 22:48:13 hifi volumio[994]: info: CorePlayQueue::getTrack 0 May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::volumioPushState May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::volumioGetState May 26 22:48:13 hifi volumio[994]: info: CorePlayQueue::getTrack 0 May 26 22:48:13 hifi volumio[994]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 26 22:48:13 hifi volumio[994]: SPOTIFY: BQBQ6j1QqE8vkd2fmrUPwOPZnYkluC5RXICAz72R78JHMVtJD6kmwQNNW1njLyuwI_mMFI61aOin84lOc69dGMlFbf-4hCD5g7HipFSYB1yEgSUjglHz0K5Q2HTjqZfshBsRPo9aVcfhZe2Axa98n6_TRCRRgs3Re6K8GbJevU42Bzw01pVy6GuCoZd0b9qDpQNiTmIS4G8xXI4DFrMYsialkhY6WCjCHNm7tdz3gFOZRO2idm_9XtN1yyv4PZiMvCdBRqFObOQvXMN6IgOXg5WD4Q May 26 22:48:13 hifi volumio[994]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 26 22:48:13 hifi volumio[994]: info: New Spotify access token = BQBQ6j1QqE8vkd2fmrUPwOPZnYkluC5RXICAz72R78JHMVtJD6kmwQNNW1njLyuwI_mMFI61aOin84lOc69dGMlFbf-4hCD5g7HipFSYB1yEgSUjglHz0K5Q2HTjqZfshBsRPo9aVcfhZe2Axa98n6_TRCRRgs3Re6K8GbJevU42Bzw01pVy6GuCoZd0b9qDpQNiTmIS4G8xXI4DFrMYsialkhY6WCjCHNm7tdz3gFOZRO2idm_9XtN1yyv4PZiMvCdBRqFObOQvXMN6IgOXg5WD4Q May 26 22:48:13 hifi volumio[994]: info: Spotify credentials grant success - running version from March 24, 2019 May 26 22:48:13 hifi go-librespot[1282]: time="2025-05-26T22:48:13+02:00" level=info msg="generated new device id: d8a9c98618d3d479e18cc2939bc440e87197be3c" May 26 22:48:13 hifi go-librespot[1282]: time="2025-05-26T22:48:13+02:00" level=debug msg="stored credentials found for jo_schndr" May 26 22:48:13 hifi volumio[994]: SPOTIFY: User informations: {"country":"FR","display_name":"Jo Shndr","email":"jonathan.jschneider@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/jo_schndr"},"followers":{"href":null,"total":4},"href":"https://api.spotify.com/v1/users/jo_schndr","id":"jo_schndr","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85092f49c5d9ac33682d453c2f","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82092f49c5d9ac33682d453c2f","width":64}],"product":"premium","type":"user","uri":"spotify:user:jo_schndr"} May 26 22:48:13 hifi volumio[994]: info: Spotify Successfully logged in May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 22:48:13 hifi volumio[994]: info: [1748292493901] CoreMusicLibrary::Adding element Spotify May 26 22:48:13 hifi volumio[994]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:48:13 hifi volumio[994]: Cannot find translation for source Spotify May 26 22:48:14 hifi go-librespot[1282]: time="2025-05-26T22:48:14+02:00" level=debug msg="obtained new client token: AAD8rNQufLizS3WOOZ0jwYxQTknahbVc3gwBjJC4mYJSLx5Nmu3pNWzh4Tfivn/3u9JpgnhE+UWYjvBwY1hHMuYEjLx37bFUcmklyzQcShfny/O1nMGGjMO8tSEFJ/EOvhMmiEch3iFMj/t2mhydVgnfaiNBH4zKTiuF6CstdMBzxPHXRIYh6cS7JYowCl9zoV8md7w/79NErRxxIrqSJhHme7huV3eT2kXSct4pt3r59jI40udb2dt5yrw=" May 26 22:48:14 hifi go-librespot[1282]: time="2025-05-26T22:48:14+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 26 22:48:14 hifi volumio[994]: info: [yt-cast-receiver] DIAL server listening on port 8098 May 26 22:48:14 hifi go-librespot[1282]: time="2025-05-26T22:48:14+02:00" level=debug msg="completed keyexchange" May 26 22:48:14 hifi mpd[1262]: May 26 22:48 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 26 22:48:14 hifi systemd[1]: Started Music Player Daemon. May 26 22:48:14 hifi sudo[1221]: pam_unix(sudo:session): session closed for user root May 26 22:48:14 hifi sudo[1214]: pam_unix(sudo:session): session closed for user root May 26 22:48:14 hifi volumio[994]: info: Completed starting Core Plugins May 26 22:48:14 hifi volumio[994]: info: ------------------------------------------- May 26 22:48:14 hifi volumio[994]: info: ----- MyVolumio plugins startup ---- May 26 22:48:14 hifi volumio[994]: info: ------------------------------------------- May 26 22:48:14 hifi volumio[994]: info: [MyVolumio PluginManager] Fetching plans data.... May 26 22:48:14 hifi volumio[994]: info: MPD running with PID1262 May 26 22:48:14 hifi volumio[994]: ,establishing connection May 26 22:48:14 hifi volumio[994]: error: MPD error: The expression evaluated to a falsy value: May 26 22:48:14 hifi volumio[994]: assert.ok(self.idling) May 26 22:48:14 hifi volumio[994]: error: The expression evaluated to a falsy value: May 26 22:48:14 hifi volumio[994]: assert.ok(self.idling) May 26 22:48:14 hifi volumio[994]: error: MPD error: The expression evaluated to a falsy value: May 26 22:48:14 hifi volumio[994]: assert.ok(self.idling) May 26 22:48:14 hifi volumio[994]: error: The expression evaluated to a falsy value: May 26 22:48:14 hifi volumio[994]: assert.ok(self.idling) May 26 22:48:14 hifi volumio[994]: error: updateQueue error: null May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="completed challenge" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="authenticated as jo_schndr" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="authenticated as jo_schndr" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="dealer connection opened" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="received connection id: MzhmNzFmYTAtYjA2Yi00NGY1LWJiZTAtZGE1NjczZmU4Y2MxK2RlYWxlcit0Y3A6Ly8wYWNhNDIzZi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNUFFNDQ4OUE3QzU3NEREMTEzMEUzM0QwRjUxMUQ2MzlFNDU2NTk5ODdENzU2QTFCMDIxMjFGODE1ODQ0NTg3RA==" May 26 22:48:15 hifi go-librespot[1282]: time="2025-05-26T22:48:15+02:00" level=debug msg="put connect state because NEW_DEVICE" May 26 22:48:16 hifi volumio[994]: info: go-librespot daemon successfully initialized May 26 22:48:18 hifi go-librespot[1282]: time="2025-05-26T22:48:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 26 22:48:18 hifi go-librespot[1282]: time="2025-05-26T22:48:18+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 250" May 26 22:48:19 hifi volumio[994]: info: Initializing connection to go-librespot Websocket May 26 22:48:19 hifi go-librespot[1282]: time="2025-05-26T22:48:19+02:00" level=debug msg="new websocket client" May 26 22:48:19 hifi volumio[994]: info: Connection to go-librespot Websocket established May 26 22:48:19 hifi volumio[994]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="handling transfer player command from 87a634f33f1ab2e6c4bff4f5716d76567105d3fe" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=trace msg="fetched new page 1 with 38 items (list: 48)" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="loading track spotify:track:1MdbDBwEEecnlLiyWChJFh (paused: false, position: 2459ms)" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=trace msg="emitting websocket event: will_play" May 26 22:48:21 hifi volumio[994]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1MdbDBwEEecnlLiyWChJFh","play_origin":"com.spotify.service.freetierartist"}} May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:1MdbDBwEEecnlLiyWChJFh" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="requested aes key for file da8d6cc6e81ef79ebb723b234f20a70c20d5b4c2, gid: 1MdbDBwEEecnlLiyWChJFh" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1663" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="fetched first chunk of 24, total size is 12322468 bytes" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=trace msg="seek to 2459ms (diff: 104ms, samples: 108441, bytes: 79421)" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=info msg="loaded track \"You & Me\" (uri: spotify:track:1MdbDBwEEecnlLiyWChJFh, paused: false, position: 2459ms, duration: 306422ms)" May 26 22:48:21 hifi go-librespot[1282]: time="2025-05-26T22:48:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1276" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=debug msg="fetched chunk 1/23, size: 524288" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=trace msg="emitting websocket event: metadata" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=trace msg="emitting websocket event: active" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=debug msg="sending successful reply for delaer request" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 26 22:48:22 hifi volumio[994]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1MdbDBwEEecnlLiyWChJFh","name":"You \u0026 Me","artist_names":["MEUTE"],"album_name":"You \u0026 Me","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021e4b57f1cfb61e9bfef1e8ca","position":2459,"duration":306422,"release_date":"year:2018 month:5 day:30","track_number":1,"disc_number":1}} May 26 22:48:22 hifi volumio[994]: SPOTIFY: received: {"type":"active","data":null} May 26 22:48:22 hifi volumio[994]: info: Aligning Spotify Volume to Volumio Volume May 26 22:48:22 hifi volumio[994]: info: CoreCommandRouter::volumioGetState May 26 22:48:22 hifi volumio[994]: info: CorePlayQueue::getTrack 0 May 26 22:48:22 hifi volumio[994]: info: Setting Spotify Volume from Volumio: 41 May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=debug msg="fetched chunk 2/23, size: 524288" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=debug msg="fetched chunk 3/23, size: 524288" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 22:48:22 hifi go-librespot[1282]: time="2025-05-26T22:48:22+02:00" level=trace msg="emitting websocket event: playing" May 26 22:48:22 hifi volumio[994]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1MdbDBwEEecnlLiyWChJFh","play_origin":"com.spotify.service.freetierartist"}} May 26 22:48:22 hifi volumio[994]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 26 22:48:22 hifi volumio[994]: TypeError: Cannot read property 'service' of undefined May 26 22:48:22 hifi volumio[994]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) May 26 22:48:22 hifi volumio[994]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) May 26 22:48:22 hifi volumio[994]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) May 26 22:48:22 hifi volumio[994]: at WebSocket.emit (events.js:315:20) May 26 22:48:22 hifi volumio[994]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) May 26 22:48:22 hifi volumio[994]: at Receiver.emit (events.js:315:20) May 26 22:48:22 hifi volumio[994]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 May 26 22:48:22 hifi volumio[994]: at internal/process/task_queues.js:149:7 May 26 22:48:22 hifi volumio[994]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) May 26 22:48:22 hifi volumio[994]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) May 26 22:48:22 hifi volumio[994]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 26 22:48:22 hifi sudo[1315]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-26 22:47 May 26 22:48:22 hifi sudo[1315]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"