-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Fri 2025-05-23 20:24:03 CEST. -- May 23 20:23:00 volumio ntpd[795]: Listen normally on 3 wlan0 192.168.1.120:123 May 23 20:23:00 volumio ntpd[795]: new interface(s) found: waking up resolver May 23 20:23:01 volumio volumio[1015]: info: ------------------------------------------- May 23 20:23:01 volumio volumio[1015]: info: ----- Volumio3 ---- May 23 20:23:01 volumio volumio[1015]: info: ------------------------------------------- May 23 20:23:01 volumio volumio[1015]: info: ----- System startup ---- May 23 20:23:01 volumio volumio[1015]: info: ------------------------------------------- May 23 20:23:01 volumio nmbd[757]: [2025/05/23 20:23:01.560420, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 23 20:23:01 volumio nmbd[757]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 23 20:23:01 volumio systemd[1]: Started Samba NMB Daemon. May 23 20:23:01 volumio systemd[1]: Starting Samba Winbind Daemon... May 23 20:23:01 volumio winbindd[1049]: [2025/05/23 20:23:01.929133, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 23 20:23:01 volumio winbindd[1049]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 23 20:23:01 volumio winbindd[1049]: [2025/05/23 20:23:01.956001, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 23 20:23:01 volumio systemd[1]: Started Samba Winbind Daemon. May 23 20:23:01 volumio winbindd[1049]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 23 20:23:02 volumio systemd[1]: Starting Samba SMB Daemon... May 23 20:23:02 volumio sh[499]: timed out May 23 20:23:02 volumio dhcpcd[546]: timed out May 23 20:23:02 volumio sh[499]: dhcpcd exited May 23 20:23:02 volumio dhcpcd[546]: dhcpcd exited May 23 20:23:02 volumio sh[499]: ifup: failed to bring up eth0 May 23 20:23:02 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 23 20:23:02 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 23 20:23:02 volumio volumio[1015]: info: MYVOLUMIO Environment detected May 23 20:23:02 volumio smbd[1057]: [2025/05/23 20:23:02.555278, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 23 20:23:02 volumio systemd[1]: Started Samba SMB Daemon. May 23 20:23:02 volumio smbd[1057]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 23 20:23:02 volumio systemd[1]: Reached target Multi-User System. May 23 20:23:02 volumio systemd[1]: Reached target Graphical Interface. May 23 20:23:02 volumio volumio[1015]: info: Plugin folders cleanup May 23 20:23:02 volumio volumio[1015]: info: Scanning into folder /volumio/app/plugins/ May 23 20:23:02 volumio volumio[1015]: info: Scanning category audio_interface May 23 20:23:02 volumio volumio[1015]: info: Scanning category miscellanea May 23 20:23:02 volumio volumio[1015]: info: Scanning category music_service May 23 20:23:02 volumio volumio[1015]: info: Scanning category plugins.json May 23 20:23:02 volumio volumio[1015]: info: Scanning category system_controller May 23 20:23:02 volumio volumio[1015]: info: Scanning category user_interface May 23 20:23:02 volumio volumio[1015]: info: Scanning into folder /data/plugins/ May 23 20:23:02 volumio volumio[1015]: info: Scanning category music_service May 23 20:23:02 volumio volumio[1015]: info: Scanning category system_hardware May 23 20:23:02 volumio volumio[1015]: info: Plugin folders cleanup completed May 23 20:23:02 volumio volumio[1015]: info: ------------------------------------------- May 23 20:23:02 volumio volumio[1015]: info: ----- Core plugins startup ---- May 23 20:23:02 volumio volumio[1015]: info: ------------------------------------------- May 23 20:23:02 volumio volumio[1015]: info: Loading plugins from folder /volumio/app/plugins/ May 23 20:23:02 volumio volumio[1015]: info: Adding plugin upnp to MyMusic Plugins May 23 20:23:02 volumio volumio[1015]: info: Adding plugin airplay_emulation to MyMusic Plugins May 23 20:23:02 volumio volumio[1015]: info: Adding plugin upnp_browser to MyMusic Plugins May 23 20:23:02 volumio volumio[1015]: info: Loading plugins from folder /data/plugins/ May 23 20:23:02 volumio volumio[1015]: info: Loading plugin "system"... May 23 20:23:02 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... May 23 20:23:02 volumio volumio[1015]: info: Loading plugin "appearance"... May 23 20:23:02 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 23 20:23:02 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. May 23 20:23:02 volumio systemd[1]: Startup finished in 15.877s (kernel) + 38.745s (userspace) = 54.622s. May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "network"... May 23 20:23:04 volumio volumio[1015]: info: Refreshing Cached IP Addresses May 23 20:23:04 volumio sudo[1073]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 23 20:23:04 volumio sudo[1073]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:04 volumio sudo[1073]: pam_unix(sudo:session): session closed for user root May 23 20:23:04 volumio sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 23 20:23:04 volumio sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:04 volumio sudo[1075]: pam_unix(sudo:session): session closed for user root May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "services"... May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "alsa_controller"... May 23 20:23:04 volumio sudo[1085]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 23 20:23:04 volumio sudo[1085]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:04 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "wizard"... May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "networkfs"... May 23 20:23:04 volumio volumio[1015]: info: Starting Udev Watcher for removable devices May 23 20:23:04 volumio sudo[1101]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=volumio,password=hocrym-Riwxyb-ruvve9,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.121/Audio/ /mnt/NAS/qnap_audio May 23 20:23:04 volumio sudo[1101]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:04 volumio volumio[1015]: info: Ignoring mount for partition: boot May 23 20:23:04 volumio volumio[1015]: info: Ignoring mount for partition: volumio May 23 20:23:04 volumio volumio[1015]: info: Ignoring mount for partition: volumio_data May 23 20:23:04 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "volumio_command_line_client"... May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "upnp"... May 23 20:23:04 volumio volumio[1015]: info: [1748024584480] Starting Upmpd Daemon May 23 20:23:04 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "my_music"... May 23 20:23:04 volumio volumio[1015]: info: Loading plugin "mpd"... May 23 20:23:04 volumio kernel: Key type cifs.spnego registered May 23 20:23:04 volumio kernel: Key type cifs.idmap registered May 23 20:23:04 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. May 23 20:23:04 volumio kernel: CIFS: Attempting to mount //192.168.1.121/Audio May 23 20:23:05 volumio volumio[1015]: info: Loading plugin "upnp_browser"... May 23 20:23:05 volumio sudo[1101]: pam_unix(sudo:session): session closed for user root May 23 20:23:05 volumio volumio[1015]: info: Loading plugin "alarm-clock"... May 23 20:23:05 volumio volumio[1015]: info: Loading plugin "airplay_emulation"... May 23 20:23:05 volumio volumio[1015]: info: Starting Shairport Sync May 23 20:23:05 volumio volumio[1015]: info: Loading plugin "last_100"... May 23 20:23:05 volumio volumio[1015]: info: Loading plugin "webradio"... May 23 20:23:05 volumio volumio[1015]: info: Loading plugin "i2s_dacs"... May 23 20:23:05 volumio volumio[1015]: info: I2S DAC not set, start Auto-detection May 23 20:23:05 volumio volumio[1015]: info: Loading plugin "volumiodiscovery"... May 23 20:23:05 volumio volumio-remote-updater[616]: [2025-05-23 20:23:05] [connect] Successful connection May 23 20:23:05 volumio volumio[1015]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 23 20:23:05 volumio volumio[1015]: *** WARNING *** Please fix your application to use the native API of Avahi! May 23 20:23:05 volumio volumio[1015]: *** WARNING *** For more information see May 23 20:23:05 volumio volumio[1015]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 23 20:23:05 volumio node[1015]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 23 20:23:05 volumio volumio[1015]: *** WARNING *** Please fix your application to use the native API of Avahi! May 23 20:23:05 volumio volumio[1015]: *** WARNING *** For more information see May 23 20:23:05 volumio node[1015]: *** WARNING *** Please fix your application to use the native API of Avahi! May 23 20:23:05 volumio node[1015]: *** WARNING *** For more information see May 23 20:23:05 volumio node[1015]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 23 20:23:05 volumio node[1015]: *** WARNING *** Please fix your application to use the native API of Avahi! May 23 20:23:05 volumio node[1015]: *** WARNING *** For more information see May 23 20:23:05 volumio volumio[1015]: info: Applying required configuration parameters for plugin volumiodiscovery May 23 20:23:05 volumio volumio[1015]: info: Discovery: Started advertising with name: Volumio May 23 20:23:05 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 23 20:23:05 volumio volumio[1015]: info: Loading plugin "mixcloud"... May 23 20:23:06 volumio systemd[1]: systemd-hostnamed.service: Succeeded. May 23 20:23:06 volumio volumio[1015]: info: Loading plugin "soundcloud"... May 23 20:23:07 volumio sudo[1085]: pam_unix(sudo:session): session closed for user root May 23 20:23:07 volumio volumio[1015]: info: Loading plugin "spop"... May 23 20:23:09 volumio volumio[1015]: info: Loading plugin "gpio-buttons"... May 23 20:23:09 volumio volumio[1015]: info: GPIO-Buttons initialized May 23 20:23:09 volumio volumio[1015]: info: Loading plugin "outputs"... May 23 20:23:09 volumio volumio[1015]: info: Loading plugin "albumart"... May 23 20:23:09 volumio volumio[1015]: info: Plugin example_plugin is not enabled May 23 20:23:09 volumio volumio[1015]: info: Loading plugin "inputs"... May 23 20:23:09 volumio volumio[1015]: info: Loading plugin "updater_comm"... May 23 20:23:10 volumio volumio[1015]: info: Plugin mpdemulation is not enabled May 23 20:23:10 volumio volumio[1015]: info: Loading plugin "rest_api"... May 23 20:23:10 volumio volumio[1015]: info: Loading plugin "websocket"... May 23 20:23:10 volumio volumio[1015]: info: Starting Socket.io Server version 2.3.0 May 23 20:23:10 volumio volumio[1015]: info: Loading i18n strings for locale de May 23 20:23:10 volumio volumio[1015]: Updating browse sources language May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:10 volumio volumio[1015]: Forking 3 albumart workers May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::initPlayerControls May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 23 20:23:10 volumio volumio[1015]: Express server listening on port 3000 May 23 20:23:10 volumio volumio[1015]: [Metrics] WebUI: 10s 331.77ms May 23 20:23:10 volumio volumio[1015]: info: CoreStateMachine::resetVolumioState May 23 20:23:10 volumio volumio[1015]: info: CoreStateMachine::getcurrentVolume May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::volumioRetrievevolume May 23 20:23:10 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:10 volumio volumio[1015]: info: Volumio Network Manager: Network status updated: 2 May 23 20:23:10 volumio volumio-remote-updater[616]: [2025-05-23 20:23:10] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748024585 101 May 23 20:23:10 volumio volumio[1015]: 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 23 20:23:10 volumio volumio[1015]: 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 23 20:23:10 volumio volumio[1015]: info: Reloading queue from file May 23 20:23:10 volumio volumio[1015]: info: VolumeController:: Volume=100 Mute =false May 23 20:23:11 volumio volumio[1015]: info: CoreStateMachine::pushState May 23 20:23:11 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioPushState May 23 20:23:11 volumio volumio[1015]: info: CoreStateMachine::updateTrackBlock May 23 20:23:11 volumio volumio[1015]: info: CorePlayQueue::getTrackBlock May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioRetrievevolume May 23 20:23:11 volumio volumio[1015]: info: Setting Device type: Raspberry PI May 23 20:23:11 volumio volumio[1015]: info: CoreStateMachine::setRepeat null single undefined May 23 20:23:11 volumio volumio[1015]: info: CoreStateMachine::pushState May 23 20:23:11 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioPushState May 23 20:23:11 volumio volumio[1015]: info: CoreStateMachine::setRandom null May 23 20:23:11 volumio volumio[1015]: info: CoreStateMachine::pushState May 23 20:23:11 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioPushState May 23 20:23:11 volumio volumio[1015]: Starting albumart workers May 23 20:23:11 volumio volumio[1015]: Starting albumart workers May 23 20:23:11 volumio volumio[1015]: Starting albumart workers May 23 20:23:11 volumio volumio[1015]: info: VolumeController:: Volume=100 Mute =false May 23 20:23:11 volumio volumio[1015]: info: CoreStateMachine::pushState May 23 20:23:11 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioPushState May 23 20:23:11 volumio volumio[1015]: info: Completed loading Core Plugins May 23 20:23:11 volumio volumio[1015]: info: Preparing to generate the ALSA configuration file May 23 20:23:11 volumio volumio[1015]: info: Discovery: adding 89bd2b1c-e938-4dfd-8723-5fe0c23ab6f4 May 23 20:23:11 volumio volumio[1015]: info: Discovery: Found device Volumio May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:11 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:11 volumio volumio[1015]: info: Asound.conf file unchanged, so no further update is needed May 23 20:23:11 volumio volumio[1015]: info: Output device has changed, restarting MPD May 23 20:23:11 volumio volumio[1015]: info: Output device has changed, restarting Shairport Sync May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:11 volumio sudo[1172]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 23 20:23:11 volumio sudo[1172]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:11 volumio sudo[1172]: pam_unix(sudo:session): session closed for user root May 23 20:23:11 volumio sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 23 20:23:11 volumio sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:11 volumio volumio[1015]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 23 20:23:11 volumio volumio[1015]: info: ___________ START PLUGINS ___________ May 23 20:23:11 volumio volumio[1015]: info: ControllerMpd::onStart: Initializing MPD May 23 20:23:11 volumio volumio[1015]: info: Creating MPD Configuration file May 23 20:23:11 volumio systemd[1]: Stopping Music Player Daemon... May 23 20:23:11 volumio sudo[1181]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:11 volumio volumio[1015]: info: [1748024591642] CoreMusicLibrary::Adding element Medienserver May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:11 volumio sudo[1183]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 23 20:23:11 volumio sudo[1181]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:11 volumio sudo[1183]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:11 volumio sudo[1181]: pam_unix(sudo:session): session closed for user root May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:11 volumio volumio[1015]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:11 volumio systemd[1]: mpd.service: Succeeded. May 23 20:23:11 volumio systemd[1]: Stopped Music Player Daemon. May 23 20:23:11 volumio systemd[1]: Starting Music Player Daemon... May 23 20:23:11 volumio volumio[1015]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:11 volumio volumio[1015]: info: [1748024591852] CoreMusicLibrary::Adding element Last_100 May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:11 volumio volumio[1015]: info: [1748024591856] CoreMusicLibrary::Adding element Webradio May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:11 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 23 20:23:11 volumio volumio[1015]: info: Initializing BBC Radios May 23 20:23:11 volumio sudo[1194]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 23 20:23:11 volumio sudo[1194]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:11 volumio sudo[1194]: pam_unix(sudo:session): session closed for user root May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:12 volumio volumio[1015]: info: [1748024592032] CoreMusicLibrary::Adding element Mixcloud May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:12 volumio volumio[1015]: Cannot find translation for source Mixcloud May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:12 volumio volumio[1015]: info: [1748024592049] CoreMusicLibrary::Adding element SoundCloud May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:12 volumio volumio[1015]: Cannot find translation for source Mixcloud May 23 20:23:12 volumio volumio[1015]: Cannot find translation for source SoundCloud May 23 20:23:12 volumio volumio[1015]: info: Creating Spotify config file May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: GPIO-Buttons: Reading config and creating triggers... May 23 20:23:12 volumio volumio[1015]: info: Volumio Calling Home May 23 20:23:12 volumio volumio[1015]: info: GPIO-Buttons started May 23 20:23:12 volumio volumio[1015]: info: MPD Permissions set May 23 20:23:12 volumio volumio[1015]: info: MPD Permissions set May 23 20:23:12 volumio volumio[1015]: info: Spotify config file written May 23 20:23:12 volumio volumio[1015]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 May 23 20:23:12 volumio volumio[1015]: info: Volumio called home May 23 20:23:12 volumio sudo[1241]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio sudo[1241]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:12 volumio volumio[1015]: info: No need to fix Spotify hosts May 23 20:23:12 volumio systemd[1]: Started go-librespot Daemon. May 23 20:23:12 volumio sudo[1241]: pam_unix(sudo:session): session closed for user root May 23 20:23:12 volumio go-librespot[1247]: go-librespot daemon starting... May 23 20:23:12 volumio volumio[1015]: info: Starting Shairport Sync May 23 20:23:12 volumio volumio[1015]: info: Starting Shairport Sync May 23 20:23:12 volumio volumio[1015]: info: Starting Shairport Sync May 23 20:23:12 volumio sudo[1259]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 23 20:23:12 volumio sudo[1259]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:12 volumio sudo[1261]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 23 20:23:12 volumio sudo[1261]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:12 volumio volumio[1015]: info: An error occurred while refreshing Spotify Token Error: Bad Request May 23 20:23:12 volumio sudo[1264]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 23 20:23:12 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 23 20:23:12 volumio sudo[1264]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:12 volumio systemd[1]: shairport-sync.service: Succeeded. May 23 20:23:12 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 23 20:23:12 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:12 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:12 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 23 20:23:12 volumio sudo[1259]: pam_unix(sudo:session): session closed for user root May 23 20:23:12 volumio sudo[1261]: pam_unix(sudo:session): session closed for user root May 23 20:23:12 volumio volumio[1015]: info: Shairport-Sync Started May 23 20:23:12 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 23 20:23:12 volumio systemd[1]: shairport-sync.service: Succeeded. May 23 20:23:12 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 23 20:23:12 volumio volumio[1015]: Error adding Membership: Error: addMembership EINVAL May 23 20:23:12 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 23 20:23:12 volumio volumio[1015]: info: Shairport-Sync Started May 23 20:23:12 volumio sudo[1264]: pam_unix(sudo:session): session closed for user root May 23 20:23:12 volumio volumio[1015]: info: Shairport-Sync Started May 23 20:23:13 volumio sudo[1274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 23 20:23:13 volumio sudo[1271]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 23 20:23:13 volumio sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:13 volumio sudo[1271]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:13 volumio sudo[1274]: pam_unix(sudo:session): session closed for user root May 23 20:23:13 volumio sudo[1271]: pam_unix(sudo:session): session closed for user root May 23 20:23:13 volumio volumio[1015]: verbose: New Socket.io Connection to 192.168.1.120 from 192.168.1.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.5 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 4 May 23 20:23:13 volumio go-librespot[1247]: time="2025-05-23T20:23:13+02:00" level=info msg="running go-librespot 0.2.0" May 23 20:23:13 volumio go-librespot[1247]: time="2025-05-23T20:23:13+02:00" level=debug msg="app state loaded" May 23 20:23:13 volumio go-librespot[1247]: time="2025-05-23T20:23:13+02:00" level=debug msg="stored credentials not found" May 23 20:23:13 volumio go-librespot[1247]: time="2025-05-23T20:23:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::volumioGetVisibleSources May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:13 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 23 20:23:13 volumio volumio[1015]: info: Received Get System Info May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 23 20:23:13 volumio volumio[1015]: info: Discovery: Getting this device information May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:13 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:13 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:13 volumio volumio[1015]: info: Listing playlists May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 23 20:23:13 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 23 20:23:13 volumio go-librespot[1247]: time="2025-05-23T20:23:13+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 23 20:23:13 volumio go-librespot[1247]: time="2025-05-23T20:23:13+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 23 20:23:13 volumio go-librespot[1247]: time="2025-05-23T20:23:13+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 23 20:23:13 volumio go-librespot[1247]: time="2025-05-23T20:23:13+02:00" level=info msg="zeroconf server listening on port 32951" May 23 20:23:13 volumio mpd[1220]: May 23 20:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 23 20:23:13 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 23 20:23:13 volumio systemd[1]: mpd.service: Failed with result 'protocol'. May 23 20:23:13 volumio systemd[1]: Failed to start Music Player Daemon. May 23 20:23:13 volumio sudo[1183]: pam_unix(sudo:session): session closed for user root May 23 20:23:13 volumio sudo[1174]: pam_unix(sudo:session): session closed for user root May 23 20:23:13 volumio volumio[1015]: error: Cannot start MPD on system Start: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service May 23 20:23:13 volumio volumio[1015]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. May 23 20:23:13 volumio volumio[1015]: See "systemctl status mpd.service" and "journalctl -xe" for details. May 23 20:23:13 volumio volumio[1015]: info: Completed starting Core Plugins May 23 20:23:13 volumio volumio[1015]: info: ------------------------------------------- May 23 20:23:13 volumio volumio[1015]: info: ----- MyVolumio plugins startup ---- May 23 20:23:13 volumio volumio[1015]: info: ------------------------------------------- May 23 20:23:13 volumio volumio[1015]: info: [MyVolumio PluginManager] Fetching plans data.... May 23 20:23:13 volumio volumio[1015]: info: Cannot restart MPD: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service May 23 20:23:13 volumio volumio[1015]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. May 23 20:23:13 volumio volumio[1015]: See "systemctl status mpd.service" and "journalctl -xe" for details. May 23 20:23:13 volumio systemd[1]: Starting Music Player Daemon... May 23 20:23:13 volumio sudo[1282]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 23 20:23:13 volumio sudo[1282]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:13 volumio sudo[1282]: pam_unix(sudo:session): session closed for user root May 23 20:23:14 volumio sudo[1300]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 23 20:23:14 volumio sudo[1300]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:14 volumio sudo[1300]: pam_unix(sudo:session): session closed for user root May 23 20:23:14 volumio sudo[1302]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 23 20:23:14 volumio sudo[1302]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:14 volumio sudo[1302]: pam_unix(sudo:session): session closed for user root May 23 20:23:14 volumio sudo[1306]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 23 20:23:14 volumio sudo[1306]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:14 volumio systemd[1]: Started UPnP Renderer front-end to MPD. May 23 20:23:14 volumio sudo[1306]: pam_unix(sudo:session): session closed for user root May 23 20:23:14 volumio volumio[1015]: info: Upmpdcli Daemon Started May 23 20:23:14 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 23 20:23:14 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 23 20:23:14 volumio volumio[1015]: info: Received Get System Info May 23 20:23:14 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 23 20:23:14 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 23 20:23:14 volumio volumio[1015]: info: Discovery: Getting this device information May 23 20:23:14 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:14 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:14 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 23 20:23:15 volumio mpd[1284]: May 23 20:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 23 20:23:15 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken May 23 20:23:15 volumio volumio[1015]: info: go-librespot daemon successfully initialized May 23 20:23:16 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 23 20:23:16 volumio volumio[1015]: info: Received Get System Info May 23 20:23:16 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 23 20:23:16 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 23 20:23:16 volumio volumio[1015]: info: Discovery: Getting this device information May 23 20:23:16 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:16 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:16 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 23 20:23:16 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken May 23 20:23:17 volumio systemd[1]: Started Music Player Daemon. May 23 20:23:17 volumio volumio[1015]: Upnp client error: Error: This socket has been ended by the other party May 23 20:23:17 volumio mpd_monitor.sh[611]: MPD restarted due to no mpc output. May 23 20:23:17 volumio volumio[1015]: error: MPD error: The expression evaluated to a falsy value: May 23 20:23:17 volumio volumio[1015]: assert.ok(self.idling) May 23 20:23:17 volumio volumio[1015]: error: The expression evaluated to a falsy value: May 23 20:23:17 volumio volumio[1015]: assert.ok(self.idling) May 23 20:23:17 volumio volumio[1015]: error: updateQueue error: null May 23 20:23:18 volumio volumio[1015]: info: Initializing connection to go-librespot Websocket May 23 20:23:18 volumio go-librespot[1247]: time="2025-05-23T20:23:18+02:00" level=debug msg="new websocket client" May 23 20:23:18 volumio volumio[1015]: info: Connection to go-librespot Websocket established May 23 20:23:18 volumio volumio[1308]: Generating RSA private key, 4096 bit long modulus (2 primes) May 23 20:23:20 volumio go-librespot[1247]: time="2025-05-23T20:23:20+02:00" level=debug msg="obtained new client token: AAAe298xj2ykAG5uND/KfARLCZ332fRUiYJjnh7EbeOnnP6Pj79qf/Fk/Ja+dJipwLPl8oN/RxxznLGEvxRN2SlV+8w+Y2kqgNxi30HgbWNm3NNoLnDNEoXD/OjXV9leTcOSRo6I1iXq0/19r6pbjH1P8OvVNPgtDESQYWT2QsW1tTjxd1OZXrJCJaiPcKNwZOaOPd+1mE4LA/MfipZCzLx0NrujOMe0CnY9dutBlvYuEr/A0fV+GPHVmk4=" May 23 20:23:20 volumio go-librespot[1247]: time="2025-05-23T20:23:20+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" May 23 20:23:20 volumio go-librespot[1247]: time="2025-05-23T20:23:20+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" May 23 20:23:20 volumio go-librespot[1247]: time="2025-05-23T20:23:20+02:00" level=debug msg="completed keyexchange" May 23 20:23:20 volumio go-librespot[1247]: time="2025-05-23T20:23:20+02:00" level=debug msg="completed challenge" May 23 20:23:20 volumio go-librespot[1247]: time="2025-05-23T20:23:20+02:00" level=info msg="authenticated AP as 3v5o3xhu9nfle3qnuuvz7xy8s" May 23 20:23:20 volumio go-librespot[1247]: time="2025-05-23T20:23:20+02:00" level=info msg="authenticated Login5 as 3v5o3xhu9nfle3qnuuvz7xy8s" May 23 20:23:20 volumio go-librespot[1247]: time="2025-05-23T20:23:20+02:00" level=info msg="accepted zeroconf user 3v5o3xhu9nfle3qnuuvz7xy8s from iPhone" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="dealer connection opened" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="starting accesspoint recv loop" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="starting dealer recv loop" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="received accesspoint ping" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="received connection id: ZTc2MGFiMWQtNzVkZi00ZjIxLWI3OTUtODdiOGMyZTIwMmQzK2RlYWxlcit0Y3A6Ly8wYWNhNWE1NC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNjEzNThEOUI4RkVBRkJDNTE1QTQ1MDgxOTgxMEQyNEEyQzhEQzgxNjNFOEZBMzY0QTU2QUIzOUMyMzg3NThFRA==" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="received accesspoint pong ack" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="put connect state because NEW_DEVICE" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="handling transfer player command from 811282120644a60e87953a3f1fb89b2909bb59c7" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="resolved context of track" uri="spotify:search:boo" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:boo" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="loading track (paused: true, position: 6381ms)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="emitting websocket event: will_play" May 23 20:23:21 volumio volumio[1015]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5rYJbmPYDaC4yJ8toRSrof","play_origin":"search"}} May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="selected format OGG_VORBIS_320 (5b6a37fcbe9d2853a2f911b5434d5651e29a0e26)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="requested aes key for file 5b6a37fcbe9d2853a2f911b5434d5651e29a0e26, gid: 5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 23 20:23:21 volumio volumio[1308]: ....................++++ May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1358" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1123" May 23 20:23:21 volumio volumio[1015]: info: Getting Spotify volume May 23 20:23:21 volumio volumio[1015]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="fetched first chunk of 21, total size is 10933280 bytes" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="seek to 6381ms (diff: 254ms, samples: 281402, bytes: 243922)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="created new output device" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=info msg="loaded track \"Boom Shack-A-Lak\" (paused: true, position: 6381ms, duration: 271333ms, prefetched: false)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:21 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="emitting websocket event: metadata" May 23 20:23:21 volumio volumio[1015]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 23 20:23:21 volumio volumio[1015]: SPOTIFY: SPOTIFY VOLUME undefined May 23 20:23:21 volumio volumio[1015]: SPOTIFY: VOLUMIO VOLUME 100 May 23 20:23:21 volumio volumio[1015]: info: Aligning Spotify Volume to Volumio Volume May 23 20:23:21 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:21 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:21 volumio volumio[1015]: info: Setting Spotify Volume from Volumio: 100 May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="emitting websocket event: active" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="sending successful reply for dealer request" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 23 20:23:21 volumio volumio[1015]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5rYJbmPYDaC4yJ8toRSrof","name":"Boom Shack-A-Lak","artist_names":["Apache Indian"],"album_name":"Make Way For The Indian","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a727272868ef7aa405548a2d","position":6381,"duration":271333,"release_date":"year:1995 month:1 day:1","track_number":11,"disc_number":1}} May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 23 20:23:21 volumio volumio[1015]: SPOTIFY: received: {"type":"active","data":null} May 23 20:23:21 volumio volumio[1015]: info: Aligning Spotify Volume to Volumio Volume May 23 20:23:21 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:21 volumio volumio[1015]: info: CorePlayQueue::getTrack 0 May 23 20:23:21 volumio volumio[1015]: info: Setting Spotify Volume from Volumio: 100 May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio volumio[1015]: info: Spotify volume: 100 May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=trace msg="emitting websocket event: paused" May 23 20:23:21 volumio volumio[1015]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5rYJbmPYDaC4yJ8toRSrof","play_origin":"search"}} May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio volumio[1015]: info: Spotify is playing in volatile mode May 23 20:23:21 volumio volumio[1015]: info: CoreStateMachine::setConsumeUpdateService undefined May 23 20:23:21 volumio volumio[1015]: SPOTIFY: UNSET VOLATILE May 23 20:23:21 volumio volumio[1015]: SPOTIFY: {"status":"stop","position":0,"title":"Navarra,Barbirolli,Schwarz - Elgar & Dvorak Cello concertos.flac","artist":"Navarra,Barbirolli,Schwarz","album":"Elgar & Dvorak Cello concertos","albumart":"/albumart?cacheid=577&web=Navarra%2CBarbirolli%2CSchwarz/Elgar%20%26%20Dvorak%20Cello%20concertos/extralarge&path=%2FNAS%2Fqnap_audio%2Flossless%2FElgar%2C%20Dvorak%20-%20Cello%20concertos%20-%20Navarra&metadata=false","uri":"mnt/NAS/qnap_audio/lossless/Elgar, Dvorak - Cello concertos - Navarra/Navarra,Barbirolli,Schwarz - Elgar & Dvorak Cello concertos.flac","trackType":"flac","seek":0,"duration":3892,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"flac","updatedb":false,"volatile":false,"service":"mpd"} May 23 20:23:21 volumio volumio[1015]: SPOTIFY: PUSH STATE SPOTIFY May 23 20:23:21 volumio volumio[1015]: SPOTIFY: {"status":"pause","service":"spop","title":"Boom Shack-A-Lak","artist":"Apache Indian","album":"Make Way For The Indian","albumart":"https://i.scdn.co/image/ab67616d00001e02a727272868ef7aa405548a2d","uri":"spotify:track:5rYJbmPYDaC4yJ8toRSrof","trackType":"spotify","seek":6381,"duration":271,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 23 20:23:21 volumio volumio[1015]: info: CoreCommandRouter::servicePushState May 23 20:23:21 volumio volumio[1015]: info: CoreStateMachine::pushState May 23 20:23:21 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 23 20:23:21 volumio volumio[1015]: info: CoreCommandRouter::volumioPushState May 23 20:23:21 volumio go-librespot[1247]: time="2025-05-23T20:23:21+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:21 volumio volumio[1015]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso May 23 20:23:22 volumio volumio[1015]: info: Adding plugin bluetooth to MyMusic Plugins May 23 20:23:22 volumio volumio[1015]: info: Adding plugin multiroom to MyMusic Plugins May 23 20:23:22 volumio volumio[1015]: info: Adding plugin metavolumio to MyMusic Plugins May 23 20:23:22 volumio volumio[1015]: info: Adding plugin cd_controller to MyMusic Plugins May 23 20:23:22 volumio volumio[1015]: info: Adding plugin smart_inputs to MyMusic Plugins May 23 20:23:22 volumio volumio[1015]: info: Adding plugin tidalconnect to MyMusic Plugins May 23 20:23:22 volumio volumio[1015]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... May 23 20:23:23 volumio volumio[1015]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded May 23 20:23:23 volumio volumio[1015]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio May 23 20:23:23 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:23 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:23 volumio volumio[1015]: info: Starting MyVolumio Remote Streaming Endpoints May 23 20:23:23 volumio volumio[1015]: info: MyVolumio login type: Token May 23 20:23:23 volumio volumio[1015]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started May 23 20:23:23 volumio volumio[1015]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... May 23 20:23:23 volumio go-librespot[1247]: time="2025-05-23T20:23:23+02:00" level=debug msg="handling resume player command from 811282120644a60e87953a3f1fb89b2909bb59c7" May 23 20:23:23 volumio go-librespot[1247]: time="2025-05-23T20:23:23+02:00" level=trace msg="seek to 6381ms (diff: 254ms, samples: 281402, bytes: 243922)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:24 volumio go-librespot[1247]: time="2025-05-23T20:23:24+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" May 23 20:23:24 volumio go-librespot[1247]: time="2025-05-23T20:23:24+02:00" level=debug msg="resume track at 6127ms" May 23 20:23:24 volumio go-librespot[1247]: time="2025-05-23T20:23:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:23:24 volumio go-librespot[1247]: time="2025-05-23T20:23:24+02:00" level=trace msg="scheduling prefetch in 235s" May 23 20:23:24 volumio go-librespot[1247]: time="2025-05-23T20:23:24+02:00" level=debug msg="sending successful reply for dealer request" May 23 20:23:24 volumio go-librespot[1247]: time="2025-05-23T20:23:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:23:24 volumio go-librespot[1247]: time="2025-05-23T20:23:24+02:00" level=trace msg="emitting websocket event: playing" May 23 20:23:24 volumio volumio[1015]: info: Starting Streaming Service Transparent Proxy May 23 20:23:24 volumio volumio[1015]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded May 23 20:23:24 volumio volumio[1015]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services May 23 20:23:24 volumio volumio[1015]: info: Streaming services startup May 23 20:23:24 volumio volumio[1015]: info: Starting Streaming Daemon May 23 20:23:25 volumio sudo[1350]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 23 20:23:25 volumio sudo[1350]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:25 volumio volumio[1015]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started May 23 20:23:25 volumio sudo[1350]: pam_unix(sudo:session): session closed for user root May 23 20:23:25 volumio volumio[1015]: SPOTIFY: SETTING SPOTIFY VOLUME 100 May 23 20:23:25 volumio volumio[1015]: info: Sending Spotify command with payload to local API: /player/volume May 23 20:23:25 volumio volumio[1015]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5rYJbmPYDaC4yJ8toRSrof","play_origin":"search"}} May 23 20:23:25 volumio volumio[1015]: SPOTIFY: PUSH STATE SPOTIFY May 23 20:23:25 volumio volumio[1015]: SPOTIFY: {"status":"play","service":"spop","title":"Boom Shack-A-Lak","artist":"Apache Indian","album":"Make Way For The Indian","albumart":"https://i.scdn.co/image/ab67616d00001e02a727272868ef7aa405548a2d","uri":"spotify:track:5rYJbmPYDaC4yJ8toRSrof","trackType":"spotify","seek":6381,"duration":271,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 23 20:23:25 volumio volumio[1015]: info: CoreCommandRouter::servicePushState May 23 20:23:25 volumio volumio[1015]: info: CoreStateMachine::pushState May 23 20:23:25 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 23 20:23:25 volumio volumio[1015]: info: CoreCommandRouter::volumioPushState May 23 20:23:25 volumio go-librespot[1247]: time="2025-05-23T20:23:25+02:00" level=debug msg="update volume to 65535/65535" May 23 20:23:25 volumio volumio[1015]: error: Cannot start Volumio Streaming Daemon May 23 20:23:25 volumio volumio[1015]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 23 20:23:25 volumio volumio[1015]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 23 20:23:25 volumio volumio[1015]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 23 20:23:25 volumio volumio[1015]: error: MyVolumio Custom Token format not valid, refreshing it May 23 20:23:25 volumio volumio[1015]: SPOTIFY: PUSH STATE SPOTIFY May 23 20:23:25 volumio volumio[1015]: SPOTIFY: {"status":"play","service":"spop","title":"Boom Shack-A-Lak","artist":"Apache Indian","album":"Make Way For The Indian","albumart":"https://i.scdn.co/image/ab67616d00001e02a727272868ef7aa405548a2d","uri":"spotify:track:5rYJbmPYDaC4yJ8toRSrof","trackType":"spotify","seek":6381,"duration":271,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 23 20:23:25 volumio volumio[1015]: info: CoreCommandRouter::servicePushState May 23 20:23:25 volumio volumio[1015]: info: CoreStateMachine::pushState May 23 20:23:25 volumio volumio[1015]: info: CoreCommandRouter::volumioPushState May 23 20:23:25 volumio volumio[1015]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 23 20:23:26 volumio volumio[1015]: info: MyVolumio login type: Token May 23 20:23:26 volumio go-librespot[1247]: time="2025-05-23T20:23:26+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 23 20:23:26 volumio go-librespot[1247]: time="2025-05-23T20:23:26+02:00" level=trace msg="emitting websocket event: volume" May 23 20:23:26 volumio volumio[1015]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} May 23 20:23:26 volumio volumio[1015]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 May 23 20:23:26 volumio volumio[1015]: STREAMING PROXY: Starting server on port 3245 May 23 20:23:26 volumio volumio[1015]: Node JS runtime: 14 May 23 20:23:26 volumio volumio[1015]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN May 23 20:23:27 volumio volumio[1015]: info: MyVolumio token set successfully May 23 20:23:27 volumio volumio[1015]: info: MYVOLUMIO: Adding device May 23 20:23:27 volumio volumio[1015]: info: MYVOLUMIO: Evaluating Server May 23 20:23:27 volumio volumio[1015]: info: MyVolumio status changed May 23 20:23:27 volumio volumio[1015]: info: Streaming services startup May 23 20:23:27 volumio volumio[1015]: info: Starting Streaming Daemon May 23 20:23:27 volumio volumio[1015]: info: Removing browser output: myVolumio user plan is not superstar May 23 20:23:27 volumio volumio[1015]: info: Removing audio output: May 23 20:23:27 volumio volumio[1015]: info: Stoppping Tunnel 1 May 23 20:23:27 volumio sudo[1377]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 23 20:23:27 volumio sudo[1377]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:27 volumio sudo[1377]: pam_unix(sudo:session): session closed for user root May 23 20:23:27 volumio volumio[1015]: error: Cannot start Volumio Streaming Daemon May 23 20:23:27 volumio volumio[1015]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 23 20:23:27 volumio volumio[1015]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 23 20:23:27 volumio sudo[1380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service May 23 20:23:27 volumio sudo[1380]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:27 volumio sudo[1380]: pam_unix(sudo:session): session closed for user root May 23 20:23:27 volumio volumio[1015]: info: Remote SSH Stopped May 23 20:23:27 volumio volumio[1015]: info: Setting Geolocation for MyVolumio to eu4 May 23 20:23:27 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:27 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:28 volumio volumio[1015]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} May 23 20:23:28 volumio volumio[1015]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 23 20:23:28 volumio volumio[1015]: info: Updating MyVolumio device info May 23 20:23:28 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:28 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:28 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:28 volumio volumio[1308]: ............................................................++++ May 23 20:23:28 volumio volumio[1308]: e is 65537 (0x010001) May 23 20:23:28 volumio volumio[1308]: writing RSA key May 23 20:23:29 volumio systemd[1]: systemd-timedated.service: Succeeded. May 23 20:23:29 volumio volumio[1015]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} May 23 20:23:29 volumio go-librespot[1247]: time="2025-05-23T20:23:29+02:00" level=debug msg="fetched chunk 4/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:32 volumio volumio[1015]: info: MYVOLUMIO: Adding device May 23 20:23:32 volumio volumio[1015]: info: MYVOLUMIO: Evaluating Server May 23 20:23:33 volumio volumio[1015]: info: Setting Geolocation for MyVolumio to eu6 May 23 20:23:33 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:35 volumio volumio[1015]: info: Updating MyVolumio device info May 23 20:23:35 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:35 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:35 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:36 volumio volumio[1015]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} May 23 20:23:37 volumio volumio[1015]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} May 23 20:23:38 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 23 20:23:39 volumio volumio[1015]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 May 23 20:23:40 volumio ntpd[795]: Soliciting pool server 212.51.144.47 May 23 20:23:41 volumio volumio[1015]: info: CoreCommandRouter::volumioGetState May 23 20:23:41 volumio ntpd[795]: Soliciting pool server 212.25.15.128 May 23 20:23:42 volumio ntpd[795]: Soliciting pool server 81.94.123.16 May 23 20:23:42 volumio ntpd[795]: Soliciting pool server 193.5.60.8 May 23 20:23:42 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 23 20:23:42 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:42 volumio volumio[1015]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 23 20:23:42 volumio go-librespot[1247]: time="2025-05-23T20:23:42+02:00" level=debug msg="fetched chunk 5/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:23:43 volumio volumio[1015]: <--- Last few GCs ---> May 23 20:23:43 volumio volumio[1015]: [1015:0x40a1780] 44302 ms: Scavenge 165.4 (176.1) -> 165.4 (176.1) MB, 1.8 / 0.0 ms (average mu = 0.911, current mu = 0.906) allocation failure May 23 20:23:43 volumio volumio[1015]: [1015:0x40a1780] 44428 ms: Scavenge 187.2 (197.8) -> 187.2 (197.8) MB, 0.8 / 0.0 ms (average mu = 0.911, current mu = 0.906) allocation failure May 23 20:23:43 volumio volumio[1015]: <--- JS stacktrace ---> May 23 20:23:43 volumio volumio[1015]: FATAL ERROR: MarkCompactCollector: young object promotion failed Allocation failed - JavaScript heap out of memory May 23 20:23:43 volumio volumio-remote-updater[616]: [2025-05-23 20:23:43] [error] handle_read_frame error: websocketpp.transport:7 (End of File) May 23 20:23:43 volumio volumio-remote-updater[616]: [2025-05-23 20:23:43] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] May 23 20:23:43 volumio go-librespot[1247]: time="2025-05-23T20:23:43+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" May 23 20:23:43 volumio systemd[1]: volumio.service: Main process exited, code=killed, status=11/SEGV May 23 20:23:43 volumio systemd[1]: volumio.service: Failed with result 'signal'. May 23 20:23:43 volumio ntpd[795]: Soliciting pool server 212.51.144.46 May 23 20:23:43 volumio ntpd[795]: Soliciting pool server 81.6.2.165 May 23 20:23:43 volumio systemd[1]: Started dynamicswap service. May 23 20:23:43 volumio systemd[1]: dynamicswap.service: Succeeded. May 23 20:23:43 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. May 23 20:23:43 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. May 23 20:23:43 volumio systemd[1]: Stopped Volumio Backend Module. May 23 20:23:43 volumio systemd[1]: Started Volumio Backend Module. May 23 20:23:43 volumio systemd[1]: Started dynamicswap service. May 23 20:23:43 volumio systemd[1]: dynamicswap.service: Succeeded. May 23 20:23:44 volumio ntpd[795]: Soliciting pool server 156.106.214.52 May 23 20:23:44 volumio ntpd[795]: Soliciting pool server 195.186.4.100 May 23 20:23:45 volumio volumio[1479]: info: ------------------------------------------- May 23 20:23:45 volumio volumio[1479]: info: ----- Volumio3 ---- May 23 20:23:45 volumio volumio[1479]: info: ------------------------------------------- May 23 20:23:45 volumio volumio[1479]: info: ----- System startup ---- May 23 20:23:45 volumio volumio[1479]: info: ------------------------------------------- May 23 20:23:45 volumio ntpd[795]: Soliciting pool server 195.186.1.101 May 23 20:23:45 volumio ntpd[795]: Soliciting pool server 62.12.167.109 May 23 20:23:45 volumio ntpd[795]: Soliciting pool server 185.125.24.59 May 23 20:23:45 volumio volumio[1479]: info: MYVOLUMIO Environment detected May 23 20:23:45 volumio volumio[1479]: info: Plugin folders cleanup May 23 20:23:45 volumio volumio[1479]: info: Scanning into folder /volumio/app/plugins/ May 23 20:23:45 volumio volumio[1479]: info: Scanning category audio_interface May 23 20:23:45 volumio volumio[1479]: info: Scanning category miscellanea May 23 20:23:45 volumio volumio[1479]: info: Scanning category music_service May 23 20:23:45 volumio volumio[1479]: info: Scanning category plugins.json May 23 20:23:45 volumio volumio[1479]: info: Scanning category system_controller May 23 20:23:46 volumio volumio[1479]: info: Scanning category user_interface May 23 20:23:46 volumio volumio[1479]: info: Scanning into folder /data/plugins/ May 23 20:23:46 volumio volumio[1479]: info: Scanning category music_service May 23 20:23:46 volumio volumio[1479]: info: Scanning category system_hardware May 23 20:23:46 volumio volumio[1479]: info: Plugin folders cleanup completed May 23 20:23:46 volumio volumio[1479]: info: ------------------------------------------- May 23 20:23:46 volumio volumio[1479]: info: ----- Core plugins startup ---- May 23 20:23:46 volumio volumio[1479]: info: ------------------------------------------- May 23 20:23:46 volumio volumio[1479]: info: Loading plugins from folder /volumio/app/plugins/ May 23 20:23:46 volumio volumio[1479]: info: Adding plugin upnp to MyMusic Plugins May 23 20:23:46 volumio volumio[1479]: info: Adding plugin airplay_emulation to MyMusic Plugins May 23 20:23:46 volumio volumio[1479]: info: Adding plugin upnp_browser to MyMusic Plugins May 23 20:23:46 volumio volumio[1479]: info: Loading plugins from folder /data/plugins/ May 23 20:23:46 volumio volumio[1479]: info: Loading plugin "system"... May 23 20:23:46 volumio volumio[1479]: info: Loading plugin "appearance"... May 23 20:23:46 volumio ntpd[795]: Soliciting pool server 217.147.223.78 May 23 20:23:46 volumio ntpd[795]: Soliciting pool server 130.60.204.10 May 23 20:23:47 volumio volumio[1479]: info: Loading plugin "network"... May 23 20:23:47 volumio volumio[1479]: info: Refreshing Cached IP Addresses May 23 20:23:47 volumio sudo[1506]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 23 20:23:47 volumio sudo[1508]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 23 20:23:47 volumio volumio[1479]: info: Loading plugin "services"... May 23 20:23:47 volumio sudo[1506]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:47 volumio volumio[1479]: info: Loading plugin "alsa_controller"... May 23 20:23:47 volumio sudo[1506]: pam_unix(sudo:session): session closed for user root May 23 20:23:47 volumio sudo[1508]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:47 volumio sudo[1515]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 23 20:23:47 volumio sudo[1508]: pam_unix(sudo:session): session closed for user root May 23 20:23:47 volumio sudo[1515]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:47 volumio ntpd[795]: Soliciting pool server 82.197.164.46 May 23 20:23:47 volumio ntpd[795]: Soliciting pool server 82.197.162.18 May 23 20:23:48 volumio ntpd[795]: receive: Unexpected origin timestamp 0xebdb3bb3.35565fbe does not match aorg 0000000000.00000000 from server@212.51.144.46 xmt 0xebdb3bb4.544df6da May 23 20:23:48 volumio ntpd[795]: receive: Unexpected origin timestamp 0xebdb3bb3.35576ae4 does not match aorg 0000000000.00000000 from server@193.5.60.8 xmt 0xebdb3bb4.5436438b May 23 20:23:48 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 23 20:23:48 volumio volumio[1479]: info: Loading plugin "wizard"... May 23 20:23:48 volumio volumio[1479]: info: Loading plugin "networkfs"... May 23 20:23:48 volumio systemd[1]: Starting Daily apt download activities... May 23 20:23:48 volumio volumio[1479]: info: Cannot mount NAS qnap_audio at system boot, trial number 1 ,retrying in 5 seconds May 23 20:23:48 volumio volumio[1479]: info: Starting Udev Watcher for removable devices May 23 20:23:48 volumio volumio[1479]: info: Ignoring mount for partition: boot May 23 20:23:48 volumio volumio[1479]: info: Ignoring mount for partition: volumio May 23 20:23:48 volumio volumio[1479]: info: Ignoring mount for partition: volumio_data May 23 20:23:48 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 23 20:23:48 volumio volumio[1479]: info: Loading plugin "volumio_command_line_client"... May 23 20:23:48 volumio volumio[1479]: info: Loading plugin "upnp"... May 23 20:23:48 volumio volumio[1479]: info: [1748024628476] Starting Upmpd Daemon May 23 20:23:48 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 23 20:23:48 volumio volumio[1479]: info: Loading plugin "my_music"... May 23 20:23:48 volumio volumio[1479]: info: Loading plugin "mpd"... May 23 20:23:48 volumio volumio[1479]: info: Loading plugin "upnp_browser"... May 23 20:23:49 volumio volumio-remote-updater[616]: [2025-05-23 20:23:49] [connect] Successful connection May 23 20:23:49 volumio volumio[1479]: info: Loading plugin "alarm-clock"... May 23 20:23:49 volumio ntpd[795]: Soliciting pool server 2001:470:b415:2:be24:11ff:fec1:2292 May 23 20:23:49 volumio volumio[1479]: info: Loading plugin "airplay_emulation"... May 23 20:23:49 volumio volumio[1479]: info: Starting Shairport Sync May 23 20:23:49 volumio volumio[1479]: info: Loading plugin "last_100"... May 23 20:23:49 volumio volumio[1479]: info: Loading plugin "webradio"... May 23 20:23:49 volumio volumio[1479]: info: Loading plugin "i2s_dacs"... May 23 20:23:49 volumio volumio[1479]: info: I2S DAC not set, start Auto-detection May 23 20:23:49 volumio volumio[1479]: info: Loading plugin "volumiodiscovery"... May 23 20:23:49 volumio volumio[1479]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 23 20:23:49 volumio volumio[1479]: *** WARNING *** Please fix your application to use the native API of Avahi! May 23 20:23:49 volumio volumio[1479]: *** WARNING *** For more information see May 23 20:23:49 volumio node[1479]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 23 20:23:49 volumio volumio[1479]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 23 20:23:49 volumio volumio[1479]: *** WARNING *** Please fix your application to use the native API of Avahi! May 23 20:23:49 volumio volumio[1479]: *** WARNING *** For more information see May 23 20:23:49 volumio node[1479]: *** WARNING *** Please fix your application to use the native API of Avahi! May 23 20:23:49 volumio node[1479]: *** WARNING *** For more information see May 23 20:23:49 volumio node[1479]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 23 20:23:49 volumio node[1479]: *** WARNING *** Please fix your application to use the native API of Avahi! May 23 20:23:49 volumio node[1479]: *** WARNING *** For more information see May 23 20:23:49 volumio volumio[1479]: info: Applying required configuration parameters for plugin volumiodiscovery May 23 20:23:49 volumio volumio[1479]: info: Discovery: Started advertising with name: Volumio May 23 20:23:49 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 23 20:23:49 volumio volumio[1479]: info: Loading plugin "mixcloud"... May 23 20:23:50 volumio volumio[1479]: info: Loading plugin "soundcloud"... May 23 20:23:50 volumio volumio[1479]: info: Loading plugin "spop"... May 23 20:23:51 volumio sudo[1515]: pam_unix(sudo:session): session closed for user root May 23 20:23:51 volumio systemd[1]: apt-daily.service: Succeeded. May 23 20:23:51 volumio systemd[1]: Started Daily apt download activities. May 23 20:23:52 volumio volumio[1479]: info: Loading plugin "gpio-buttons"... May 23 20:23:52 volumio go-librespot[1247]: time="2025-05-23T20:23:52+02:00" level=trace msg="sent dealer ping" May 23 20:23:52 volumio go-librespot[1247]: time="2025-05-23T20:23:52+02:00" level=trace msg="received dealer pong" May 23 20:23:52 volumio volumio[1479]: info: GPIO-Buttons initialized May 23 20:23:52 volumio volumio[1479]: info: Loading plugin "outputs"... May 23 20:23:52 volumio volumio[1479]: info: Loading plugin "albumart"... May 23 20:23:52 volumio volumio[1479]: info: Plugin example_plugin is not enabled May 23 20:23:52 volumio volumio[1479]: info: Loading plugin "inputs"... May 23 20:23:52 volumio volumio[1479]: info: Loading plugin "updater_comm"... May 23 20:23:52 volumio volumio[1479]: info: Plugin mpdemulation is not enabled May 23 20:23:52 volumio volumio[1479]: info: Loading plugin "rest_api"... May 23 20:23:52 volumio volumio[1479]: info: Loading plugin "websocket"... May 23 20:23:52 volumio volumio[1479]: info: Starting Socket.io Server version 2.3.0 May 23 20:23:52 volumio volumio[1479]: info: Loading i18n strings for locale de May 23 20:23:52 volumio volumio[1479]: Updating browse sources language May 23 20:23:52 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:53 volumio volumio[1479]: Forking 3 albumart workers May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::initPlayerControls May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 23 20:23:53 volumio volumio[1479]: Express server listening on port 3000 May 23 20:23:53 volumio volumio[1479]: [Metrics] WebUI: 7s 449.79ms May 23 20:23:53 volumio volumio[1479]: info: CoreStateMachine::resetVolumioState May 23 20:23:53 volumio volumio[1479]: info: CoreStateMachine::getcurrentVolume May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::volumioRetrievevolume May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:53 volumio volumio[1479]: info: Volumio Network Manager: Network status updated: 2 May 23 20:23:53 volumio volumio-remote-updater[616]: [2025-05-23 20:23:53] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748024629 101 May 23 20:23:53 volumio volumio[1479]: 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 23 20:23:53 volumio volumio[1479]: info: Cannot mount NAS qnap_audio at system boot, trial number 2 ,retrying in 5 seconds May 23 20:23:53 volumio volumio[1479]: 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 23 20:23:53 volumio volumio[1479]: info: Reloading queue from file May 23 20:23:53 volumio volumio[1479]: info: VolumeController:: Volume=100 Mute =false May 23 20:23:53 volumio volumio[1479]: info: CoreStateMachine::pushState May 23 20:23:53 volumio volumio[1479]: info: CorePlayQueue::getTrack 0 May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::volumioPushState May 23 20:23:53 volumio volumio[1479]: info: CoreStateMachine::updateTrackBlock May 23 20:23:53 volumio volumio[1479]: info: CorePlayQueue::getTrackBlock May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::volumioRetrievevolume May 23 20:23:53 volumio volumio[1479]: info: CoreStateMachine::setRepeat null single undefined May 23 20:23:53 volumio volumio[1479]: info: CoreStateMachine::pushState May 23 20:23:53 volumio volumio[1479]: info: CorePlayQueue::getTrack 0 May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::volumioPushState May 23 20:23:53 volumio volumio[1479]: info: CoreStateMachine::setRandom null May 23 20:23:53 volumio volumio[1479]: info: CoreStateMachine::pushState May 23 20:23:53 volumio volumio[1479]: info: CorePlayQueue::getTrack 0 May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::volumioPushState May 23 20:23:53 volumio volumio[1479]: info: Setting Device type: Raspberry PI May 23 20:23:53 volumio volumio[1479]: info: Discovery: adding 89bd2b1c-e938-4dfd-8723-5fe0c23ab6f4 May 23 20:23:53 volumio volumio[1479]: info: Discovery: Found device Volumio May 23 20:23:53 volumio volumio[1479]: info: CoreCommandRouter::volumioGetState May 23 20:23:53 volumio volumio[1479]: info: CorePlayQueue::getTrack 0 May 23 20:23:53 volumio volumio[1479]: info: VolumeController:: Volume=100 Mute =false May 23 20:23:54 volumio volumio[1479]: info: CoreStateMachine::pushState May 23 20:23:54 volumio volumio[1479]: info: CorePlayQueue::getTrack 0 May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::volumioPushState May 23 20:23:54 volumio volumio[1479]: info: Completed loading Core Plugins May 23 20:23:54 volumio volumio[1479]: info: Preparing to generate the ALSA configuration file May 23 20:23:54 volumio volumio[1479]: info: Asound.conf file unchanged, so no further update is needed May 23 20:23:54 volumio volumio[1479]: info: Output device has changed, restarting MPD May 23 20:23:54 volumio volumio[1479]: Starting albumart workers May 23 20:23:54 volumio volumio[1479]: info: Output device has changed, restarting Shairport Sync May 23 20:23:54 volumio sudo[1628]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 23 20:23:54 volumio sudo[1628]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:54 volumio sudo[1628]: pam_unix(sudo:session): session closed for user root May 23 20:23:54 volumio sudo[1630]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 23 20:23:54 volumio sudo[1630]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:54 volumio systemd[1]: Stopping Music Player Daemon... May 23 20:23:54 volumio volumio[1479]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 23 20:23:54 volumio volumio[1479]: Starting albumart workers May 23 20:23:54 volumio volumio[1479]: info: ___________ START PLUGINS ___________ May 23 20:23:54 volumio volumio[1479]: info: ControllerMpd::onStart: Initializing MPD May 23 20:23:54 volumio volumio[1479]: info: Creating MPD Configuration file May 23 20:23:54 volumio sudo[1637]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 23 20:23:54 volumio sudo[1637]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:54 volumio volumio[1479]: info: [1748024634317] CoreMusicLibrary::Adding element Medienserver May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:54 volumio sudo[1637]: pam_unix(sudo:session): session closed for user root May 23 20:23:54 volumio volumio[1479]: Starting albumart workers May 23 20:23:54 volumio sudo[1640]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 23 20:23:54 volumio sudo[1640]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:54 volumio systemd[1]: mpd.service: Succeeded. May 23 20:23:54 volumio systemd[1]: Stopped Music Player Daemon. May 23 20:23:54 volumio volumio[1479]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:54 volumio systemd[1]: Starting Music Player Daemon... May 23 20:23:54 volumio sudo[1645]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 23 20:23:54 volumio sudo[1645]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:54 volumio sudo[1645]: pam_unix(sudo:session): session closed for user root May 23 20:23:54 volumio volumio[1479]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:54 volumio volumio[1479]: info: [1748024634683] CoreMusicLibrary::Adding element Last_100 May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:54 volumio volumio[1479]: info: [1748024634688] CoreMusicLibrary::Adding element Webradio May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 23 20:23:54 volumio volumio[1479]: info: Initializing BBC Radios May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:54 volumio volumio[1479]: info: [1748024634952] CoreMusicLibrary::Adding element Mixcloud May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:54 volumio volumio[1479]: Cannot find translation for source Mixcloud May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 23 20:23:54 volumio volumio[1479]: info: [1748024634985] CoreMusicLibrary::Adding element SoundCloud May 23 20:23:54 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 23 20:23:54 volumio volumio[1479]: Cannot find translation for source Mixcloud May 23 20:23:54 volumio volumio[1479]: Cannot find translation for source SoundCloud May 23 20:23:55 volumio volumio[1479]: info: Creating Spotify config file May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: GPIO-Buttons: Reading config and creating triggers... May 23 20:23:55 volumio volumio[1479]: info: Volumio Calling Home May 23 20:23:55 volumio volumio[1479]: info: GPIO-Buttons started May 23 20:23:55 volumio volumio[1479]: info: MPD Permissions set May 23 20:23:55 volumio volumio[1479]: info: MPD Permissions set May 23 20:23:55 volumio volumio[1479]: info: Spotify config file written May 23 20:23:55 volumio volumio[1479]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 May 23 20:23:55 volumio volumio[1479]: info: Volumio called home May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio sudo[1694]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio sudo[1694]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:55 volumio systemd[1]: Stopping go-librespot Daemon... May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio systemd[1]: go-librespot-daemon.service: Succeeded. May 23 20:23:55 volumio systemd[1]: Stopped go-librespot Daemon. May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 23 20:23:55 volumio volumio[1479]: info: No need to fix Spotify hosts May 23 20:23:55 volumio systemd[1]: Started go-librespot Daemon. May 23 20:23:55 volumio go-librespot[1700]: go-librespot daemon starting... May 23 20:23:55 volumio sudo[1694]: pam_unix(sudo:session): session closed for user root May 23 20:23:55 volumio go-librespot[1700]: time="2025-05-23T20:23:55+02:00" level=info msg="running go-librespot 0.2.0" May 23 20:23:55 volumio go-librespot[1700]: time="2025-05-23T20:23:55+02:00" level=debug msg="app state loaded" May 23 20:23:55 volumio go-librespot[1700]: time="2025-05-23T20:23:55+02:00" level=debug msg="stored credentials not found" May 23 20:23:55 volumio go-librespot[1700]: time="2025-05-23T20:23:55+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 23 20:23:55 volumio volumio[1479]: info: Starting Shairport Sync May 23 20:23:55 volumio volumio[1479]: info: Starting Shairport Sync May 23 20:23:55 volumio volumio[1479]: info: Starting Shairport Sync May 23 20:23:55 volumio sudo[1712]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 23 20:23:55 volumio sudo[1712]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:55 volumio sudo[1714]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 23 20:23:55 volumio sudo[1714]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:55 volumio sudo[1718]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 23 20:23:55 volumio sudo[1718]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:55 volumio volumio[1479]: info: CoreCommandRouter::volumioGetState May 23 20:23:55 volumio volumio[1479]: info: CorePlayQueue::getTrack 0 May 23 20:23:56 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 23 20:23:56 volumio systemd[1]: shairport-sync.service: Succeeded. May 23 20:23:56 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 23 20:23:56 volumio go-librespot[1700]: time="2025-05-23T20:23:56+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 23 20:23:56 volumio go-librespot[1700]: time="2025-05-23T20:23:56+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 23 20:23:56 volumio go-librespot[1700]: time="2025-05-23T20:23:56+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 23 20:23:56 volumio go-librespot[1700]: time="2025-05-23T20:23:56+02:00" level=info msg="zeroconf server listening on port 33037" May 23 20:23:56 volumio volumio[1479]: info: An error occurred while refreshing Spotify Token Error: Bad Request May 23 20:23:56 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 23 20:23:56 volumio sudo[1718]: pam_unix(sudo:session): session closed for user root May 23 20:23:56 volumio sudo[1714]: pam_unix(sudo:session): session closed for user root May 23 20:23:56 volumio sudo[1712]: pam_unix(sudo:session): session closed for user root May 23 20:23:56 volumio volumio[1479]: info: Shairport-Sync Started May 23 20:23:56 volumio volumio[1479]: Error adding Membership: Error: addMembership EINVAL May 23 20:23:56 volumio volumio[1479]: info: Shairport-Sync Started May 23 20:23:56 volumio mpd[1650]: May 23 20:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 23 20:23:58 volumio volumio[1479]: info: Cannot mount NAS qnap_audio at system boot, trial number 3 ,retrying in 5 seconds May 23 20:23:58 volumio sudo[1741]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 23 20:23:58 volumio sudo[1741]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:58 volumio sudo[1741]: pam_unix(sudo:session): session closed for user root May 23 20:23:58 volumio sudo[1743]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 23 20:23:58 volumio sudo[1743]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:58 volumio sudo[1743]: pam_unix(sudo:session): session closed for user root May 23 20:23:58 volumio sudo[1747]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 23 20:23:58 volumio sudo[1747]: pam_unix(sudo:session): session opened for user root by (uid=0) May 23 20:23:58 volumio sudo[1747]: pam_unix(sudo:session): session closed for user root May 23 20:23:58 volumio volumio[1479]: info: Upmpdcli Daemon Started May 23 20:23:58 volumio volumio[1479]: info: go-librespot daemon successfully initialized May 23 20:23:59 volumio systemd[1]: Started Music Player Daemon. May 23 20:23:59 volumio sudo[1640]: pam_unix(sudo:session): session closed for user root May 23 20:23:59 volumio sudo[1630]: pam_unix(sudo:session): session closed for user root May 23 20:23:59 volumio volumio[1479]: info: Completed starting Core Plugins May 23 20:23:59 volumio volumio[1479]: info: ------------------------------------------- May 23 20:23:59 volumio volumio[1479]: info: ----- MyVolumio plugins startup ---- May 23 20:23:59 volumio volumio[1479]: info: ------------------------------------------- May 23 20:23:59 volumio volumio[1479]: info: [MyVolumio PluginManager] Fetching plans data.... May 23 20:23:59 volumio volumio[1479]: error: MPD error: The expression evaluated to a falsy value: May 23 20:23:59 volumio volumio[1479]: assert.ok(self.idling) May 23 20:23:59 volumio volumio[1479]: error: The expression evaluated to a falsy value: May 23 20:23:59 volumio volumio[1479]: assert.ok(self.idling) May 23 20:23:59 volumio volumio[1479]: error: updateQueue error: null May 23 20:23:59 volumio volumio[1479]: info: MPD running with PID1650 May 23 20:23:59 volumio volumio[1479]: ,establishing connection May 23 20:23:59 volumio volumio[1479]: error: updateQueue error: null May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="obtained new client token: AAB6olF7CSojZbANIuYbPSHDLkbz2pUxHo3CKO8bQRs4bNedBrXSMXP7KIE/l417mBwbFRikzxGZlAhBquBy9qFPDiPfsu1DShq9Sec9W/ZKzUTpLoxjXQ38iHGDtF+QjwjZ/9faaxTbveU30iZMABLM0iZ/FsOyk65xkBf+mBAPXFCOb2dmsFEcSJaLVUd6naMlFItqV9vELcZvxo4jBjBvEhmF0POwvKiO79V1MZMtojiuw4xrtll7" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="completed keyexchange" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="completed challenge" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=info msg="authenticated AP as 3v5o3xhu9nfle3qnuuvz7xy8s" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=info msg="authenticated Login5 as 3v5o3xhu9nfle3qnuuvz7xy8s" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=info msg="accepted zeroconf user 3v5o3xhu9nfle3qnuuvz7xy8s from iPhone" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="dealer connection opened" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=trace msg="starting accesspoint recv loop" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=trace msg="starting dealer recv loop" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=trace msg="received accesspoint ping" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="received connection id: MGY1OTJjYzAtOTNmZi00NWFmLWE3ZmItMDAzYzQ2ZjVjYTAzK2RlYWxlcit0Y3A6Ly8wYWNhNTkwNi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArOTdCMEUxMENEREUyMjc1MDY1ODVGMzNBRjEzOTUyQTUzMzlCQTM5RUQzNDQ3QjlENzg1NTc5N0ZDRDZENDlGOA==" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=trace msg="received accesspoint pong ack" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="put connect state because NEW_DEVICE" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="handling transfer player command from 811282120644a60e87953a3f1fb89b2909bb59c7" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="resolved context of track" uri="spotify:search:boo" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:boo" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="loading track (paused: true, position: 38846ms)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=trace msg="emitting websocket event: will_play" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="selected format OGG_VORBIS_320 (5b6a37fcbe9d2853a2f911b5434d5651e29a0e26)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="requested aes key for file 5b6a37fcbe9d2853a2f911b5434d5651e29a0e26, gid: 5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:00 volumio go-librespot[1700]: time="2025-05-23T20:24:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1358" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="fetched first chunk of 21, total size is 10933280 bytes" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1123" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="fetched chunk 6/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="fetched chunk 5/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="fetched chunk 4/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=trace msg="seek to 38846ms (diff: 103ms, samples: 1713108, bytes: 1587735)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="created new output device" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=info msg="loaded track \"Boom Shack-A-Lak\" (paused: true, position: 38846ms, duration: 271333ms, prefetched: false)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=trace msg="emitting websocket event: metadata" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=trace msg="emitting websocket event: active" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="sending successful reply for dealer request" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=trace msg="emitting websocket event: paused" May 23 20:24:01 volumio volumio[1479]: info: Initializing connection to go-librespot Websocket May 23 20:24:01 volumio go-librespot[1700]: time="2025-05-23T20:24:01+02:00" level=debug msg="new websocket client" May 23 20:24:01 volumio volumio[1479]: info: Connection to go-librespot Websocket established May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+02:00" level=debug msg="handling resume player command from 811282120644a60e87953a3f1fb89b2909bb59c7" May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+02:00" level=trace msg="seek to 38846ms (diff: 103ms, samples: 1713108, bytes: 1587735)" uri="spotify:track:5rYJbmPYDaC4yJ8toRSrof" May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+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" May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+02:00" level=debug msg="resume track at 38743ms" May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+02:00" level=trace msg="scheduling prefetch in 202s" May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+02:00" level=debug msg="sending successful reply for dealer request" May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 23 20:24:02 volumio go-librespot[1700]: time="2025-05-23T20:24:02+02:00" level=trace msg="emitting websocket event: playing" May 23 20:24:02 volumio volumio[1479]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5rYJbmPYDaC4yJ8toRSrof","play_origin":"search"}} May 23 20:24:02 volumio volumio[1479]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 23 20:24:02 volumio volumio[1479]: TypeError: Cannot read property 'service' of undefined May 23 20:24:02 volumio volumio[1479]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) May 23 20:24:02 volumio volumio[1479]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) May 23 20:24:02 volumio volumio[1479]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) May 23 20:24:02 volumio volumio[1479]: at WebSocket.emit (events.js:315:20) May 23 20:24:02 volumio volumio[1479]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 23 20:24:02 volumio volumio[1479]: at Receiver.emit (events.js:315:20) May 23 20:24:02 volumio volumio[1479]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 23 20:24:02 volumio volumio[1479]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 23 20:24:02 volumio volumio[1479]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 23 20:24:02 volumio volumio[1479]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 23 20:24:02 volumio volumio[1479]: at writeOrBuffer (internal/streams/writable.js:358:12) May 23 20:24:02 volumio volumio[1479]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 23 20:24:02 volumio volumio[1479]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 23 20:24:02 volumio volumio[1479]: at Socket.emit (events.js:315:20) May 23 20:24:02 volumio volumio[1479]: at addChunk (internal/streams/readable.js:309:12) May 23 20:24:02 volumio volumio[1479]: at readableAddChunk (internal/streams/readable.js:284:9) May 23 20:24:02 volumio volumio[1479]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 23 20:24:03 volumio sudo[1765]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-23 20:23 May 23 20:24:03 volumio sudo[1765]: 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"