-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Thu 2025-05-15 09:44:50 CEST. -- May 15 09:44:32 bro systemd-timedated[1016]: Changed local time to Thu May 15 09:44:32 2025 May 15 09:44:32 bro sudo[1014]: pam_unix(sudo:session): session closed for user root May 15 09:44:32 bro systemd[1]: Starting Daily apt download activities... May 15 09:44:32 bro volumio-time-update[620]: volumio-time-update-util: System time updated successfully. May 15 09:44:32 bro systemd[1]: Started Volumio Time Update Utility. May 15 09:44:32 bro ntpd[785]: Listen normally on 3 wlan0 192.168.1.113:123 May 15 09:44:32 bro ntpd[785]: new interface(s) found: waking up resolver May 15 09:44:32 bro nmbd[728]: [2025/05/15 09:44:32.960849, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 15 09:44:32 bro nmbd[728]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 15 09:44:32 bro systemd[1]: Started Samba NMB Daemon. May 15 09:44:33 bro systemd[1]: Starting Samba Winbind Daemon... May 15 09:44:33 bro winbindd[1038]: [2025/05/15 09:44:33.378286, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 15 09:44:33 bro winbindd[1038]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 15 09:44:33 bro winbindd[1038]: [2025/05/15 09:44:33.393928, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 15 09:44:33 bro systemd[1]: Started Samba Winbind Daemon. May 15 09:44:33 bro winbindd[1038]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 15 09:44:33 bro systemd[1]: Starting Samba SMB Daemon... May 15 09:44:33 bro volumio[992]: info: ------------------------------------------- May 15 09:44:33 bro volumio[992]: info: ----- Volumio3 ---- May 15 09:44:33 bro volumio[992]: info: ------------------------------------------- May 15 09:44:33 bro volumio[992]: info: ----- System startup ---- May 15 09:44:33 bro volumio[992]: info: ------------------------------------------- May 15 09:44:33 bro smbd[1043]: [2025/05/15 09:44:33.816026, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 15 09:44:33 bro systemd[1]: Started Samba SMB Daemon. May 15 09:44:33 bro smbd[1043]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 15 09:44:33 bro systemd[1]: Reached target Multi-User System. May 15 09:44:33 bro systemd[1]: Reached target Graphical Interface. May 15 09:44:33 bro systemd[1]: Starting Update UTMP about System Runlevel Changes... May 15 09:44:33 bro systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 15 09:44:33 bro systemd[1]: Started Update UTMP about System Runlevel Changes. May 15 09:44:33 bro volumio-remote-updater[613]: [2025-05-15 09:44:33] [connect] Successful connection May 15 09:44:34 bro systemd[1]: apt-daily.service: Succeeded. May 15 09:44:34 bro systemd[1]: Started Daily apt download activities. May 15 09:44:34 bro systemd[1]: Starting Daily apt upgrade and clean activities... May 15 09:44:34 bro volumio[992]: info: MYVOLUMIO Environment detected May 15 09:44:34 bro volumio[992]: info: Plugin folders cleanup May 15 09:44:34 bro volumio[992]: info: Scanning into folder /volumio/app/plugins/ May 15 09:44:34 bro volumio[992]: info: Scanning category audio_interface May 15 09:44:34 bro volumio[992]: info: Scanning category miscellanea May 15 09:44:34 bro volumio[992]: info: Scanning category music_service May 15 09:44:34 bro volumio[992]: info: Scanning category plugins.json May 15 09:44:34 bro volumio[992]: info: Scanning category system_controller May 15 09:44:34 bro volumio[992]: info: Scanning category user_interface May 15 09:44:34 bro volumio[992]: info: Scanning into folder /data/plugins/ May 15 09:44:34 bro volumio[992]: info: Scanning category music_service May 15 09:44:34 bro volumio[992]: info: Plugin folders cleanup completed May 15 09:44:34 bro volumio[992]: info: ------------------------------------------- May 15 09:44:34 bro volumio[992]: info: ----- Core plugins startup ---- May 15 09:44:34 bro volumio[992]: info: ------------------------------------------- May 15 09:44:34 bro volumio[992]: info: Loading plugins from folder /volumio/app/plugins/ May 15 09:44:34 bro volumio[992]: info: Adding plugin upnp to MyMusic Plugins May 15 09:44:34 bro volumio[992]: info: Adding plugin airplay_emulation to MyMusic Plugins May 15 09:44:34 bro volumio[992]: info: Adding plugin upnp_browser to MyMusic Plugins May 15 09:44:34 bro volumio[992]: info: Loading plugins from folder /data/plugins/ May 15 09:44:34 bro volumio[992]: info: Loading plugin "system"... May 15 09:44:34 bro volumio[992]: info: Loading plugin "appearance"... May 15 09:44:35 bro systemd[1]: apt-daily-upgrade.service: Succeeded. May 15 09:44:35 bro systemd[1]: Started Daily apt upgrade and clean activities. May 15 09:44:35 bro systemd[1]: Startup finished in 12.371s (kernel) + 27.752s (userspace) = 40.124s. May 15 09:44:35 bro volumio[992]: info: Loading plugin "network"... May 15 09:44:35 bro volumio[992]: info: Refreshing Cached IP Addresses May 15 09:44:35 bro volumio[992]: info: Loading plugin "services"... May 15 09:44:35 bro volumio[992]: info: Loading plugin "alsa_controller"... May 15 09:44:35 bro sudo[1146]: volumio : unable to resolve host bro May 15 09:44:35 bro sudo[1146]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:35 bro sudo[1148]: volumio : unable to resolve host bro May 15 09:44:35 bro sudo[1148]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:35 bro sudo[1146]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 15 09:44:35 bro sudo[1146]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:35 bro sudo[1148]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 15 09:44:35 bro sudo[1148]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:35 bro sudo[1146]: pam_unix(sudo:session): session closed for user root May 15 09:44:35 bro sudo[1148]: pam_unix(sudo:session): session closed for user root May 15 09:44:35 bro sudo[1155]: volumio : unable to resolve host bro May 15 09:44:35 bro sudo[1155]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:35 bro sudo[1155]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 15 09:44:35 bro sudo[1155]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:35 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 15 09:44:35 bro volumio[992]: info: Loading plugin "wizard"... May 15 09:44:35 bro volumio[992]: info: Loading plugin "networkfs"... May 15 09:44:35 bro volumio[992]: info: Starting Udev Watcher for removable devices May 15 09:44:35 bro volumio[992]: info: Ignoring mount for partition: boot May 15 09:44:35 bro volumio[992]: info: Ignoring mount for partition: volumio May 15 09:44:35 bro volumio[992]: info: Ignoring mount for partition: volumio_data May 15 09:44:35 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 15 09:44:35 bro volumio[992]: info: Loading plugin "volumio_command_line_client"... May 15 09:44:35 bro volumio[992]: info: Loading plugin "upnp"... May 15 09:44:35 bro volumio[992]: info: [1747295075928] Starting Upmpd Daemon May 15 09:44:35 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 15 09:44:35 bro volumio[992]: info: Loading plugin "my_music"... May 15 09:44:35 bro volumio[992]: info: Loading plugin "mpd"... May 15 09:44:36 bro sudo[1174]: volumio : unable to resolve host bro May 15 09:44:36 bro sudo[1174]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:36 bro sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=fabio,password=Bikerofhell2010,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.111/fabio /mnt/NAS/Fabio May 15 09:44:36 bro sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:36 bro kernel: Key type cifs.spnego registered May 15 09:44:36 bro kernel: Key type cifs.idmap registered May 15 09:44:36 bro 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 15 09:44:36 bro kernel: CIFS: Attempting to mount //192.168.1.111/fabio May 15 09:44:36 bro volumio[992]: info: Loading plugin "upnp_browser"... May 15 09:44:36 bro volumio[992]: info: Loading plugin "alarm-clock"... May 15 09:44:36 bro volumio[992]: info: Loading plugin "airplay_emulation"... May 15 09:44:36 bro volumio[992]: info: Starting Shairport Sync May 15 09:44:36 bro volumio[992]: info: Loading plugin "last_100"... May 15 09:44:36 bro volumio[992]: info: Loading plugin "webradio"... May 15 09:44:36 bro volumio[992]: info: Loading plugin "i2s_dacs"... May 15 09:44:36 bro volumio[992]: info: I2S DAC not set, start Auto-detection May 15 09:44:36 bro volumio[992]: info: Loading plugin "volumiodiscovery"... May 15 09:44:36 bro volumio[992]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 15 09:44:36 bro volumio[992]: *** WARNING *** Please fix your application to use the native API of Avahi! May 15 09:44:36 bro node[992]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 15 09:44:36 bro volumio[992]: *** WARNING *** For more information see May 15 09:44:36 bro volumio[992]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 15 09:44:36 bro volumio[992]: *** WARNING *** Please fix your application to use the native API of Avahi! May 15 09:44:36 bro volumio[992]: *** WARNING *** For more information see May 15 09:44:36 bro node[992]: *** WARNING *** Please fix your application to use the native API of Avahi! May 15 09:44:36 bro node[992]: *** WARNING *** For more information see May 15 09:44:36 bro node[992]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 15 09:44:36 bro node[992]: *** WARNING *** Please fix your application to use the native API of Avahi! May 15 09:44:36 bro node[992]: *** WARNING *** For more information see May 15 09:44:36 bro volumio[992]: info: Applying required configuration parameters for plugin volumiodiscovery May 15 09:44:36 bro volumio[992]: info: Discovery: Started advertising with name: Büro May 15 09:44:36 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 15 09:44:36 bro volumio[992]: info: Plugin jellyfin is not enabled May 15 09:44:36 bro volumio[992]: info: Loading plugin "spop"... May 15 09:44:37 bro volumio[992]: info: Loading plugin "outputs"... May 15 09:44:37 bro volumio[992]: info: Loading plugin "albumart"... May 15 09:44:37 bro volumio[992]: info: Plugin example_plugin is not enabled May 15 09:44:37 bro volumio[992]: info: Loading plugin "inputs"... May 15 09:44:37 bro volumio[992]: info: Loading plugin "updater_comm"... May 15 09:44:38 bro volumio[992]: info: Plugin mpdemulation is not enabled May 15 09:44:38 bro volumio[992]: info: Loading plugin "rest_api"... May 15 09:44:38 bro volumio[992]: info: Loading plugin "websocket"... May 15 09:44:38 bro volumio[992]: info: Starting Socket.io Server version 2.3.0 May 15 09:44:38 bro volumio[992]: info: Loading plugin "80s80s"... May 15 09:44:38 bro volumio[992]: Forking 3 albumart workers May 15 09:44:38 bro volumio[992]: info: Applying required configuration parameters for plugin 80s80s May 15 09:44:38 bro volumio[992]: info: [1747295078436] [80s80s] API delay: 30 May 15 09:44:38 bro volumio[992]: info: Loading plugin "RoonBridge"... May 15 09:44:38 bro volumio[992]: Starting albumart workers May 15 09:44:38 bro volumio[992]: Starting albumart workers May 15 09:44:38 bro volumio[992]: Starting albumart workers May 15 09:44:38 bro volumio[992]: info: Applying required configuration parameters for plugin RoonBridge May 15 09:44:38 bro volumio[992]: info: Loading i18n strings for locale de May 15 09:44:38 bro volumio[992]: Updating browse sources language May 15 09:44:38 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::initPlayerControls May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 15 09:44:39 bro volumio[992]: Express server listening on port 3000 May 15 09:44:39 bro volumio[992]: [Metrics] WebUI: 6s 305.89ms May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::resetVolumioState May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::getcurrentVolume May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::volumioRetrievevolume May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 09:44:39 bro volumio[992]: info: Volumio Network Manager: Network status updated: 2 May 15 09:44:39 bro volumio[992]: info: Reloading queue from file May 15 09:44:39 bro volumio[992]: info: VolumeController:: Volume=64 Mute =false May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::pushState May 15 09:44:39 bro volumio[992]: info: CorePlayQueue::getTrack 0 May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::volumioPushState May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::updateTrackBlock May 15 09:44:39 bro volumio[992]: info: CorePlayQueue::getTrackBlock May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::volumioRetrievevolume May 15 09:44:39 bro volumio[992]: info: Setting Device type: Raspberry PI May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::setRepeat null single undefined May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::pushState May 15 09:44:39 bro volumio[992]: info: CorePlayQueue::getTrack 0 May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::volumioPushState May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::setRandom null May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::pushState May 15 09:44:39 bro volumio[992]: info: CorePlayQueue::getTrack 0 May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::volumioPushState May 15 09:44:39 bro volumio[992]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb May 15 09:44:39 bro volumio[992]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 May 15 09:44:39 bro volumio[992]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI May 15 09:44:39 bro volumio[992]: info: VolumeController:: Volume=64 Mute =false May 15 09:44:39 bro volumio[992]: info: CoreStateMachine::pushState May 15 09:44:39 bro volumio[992]: info: CorePlayQueue::getTrack 0 May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::volumioPushState May 15 09:44:39 bro sudo[1155]: pam_unix(sudo:session): session closed for user root May 15 09:44:39 bro volumio[992]: info: Discovery: adding bdda3456-5ab4-4f6a-bc7c-13c6e864e0e0 May 15 09:44:39 bro volumio[992]: info: Discovery: Found device Büro May 15 09:44:39 bro volumio[992]: info: CoreCommandRouter::volumioGetState May 15 09:44:39 bro volumio[992]: info: CorePlayQueue::getTrack 0 May 15 09:44:40 bro systemd[1]: systemd-fsckd.service: Succeeded. May 15 09:44:41 bro sh[517]: timed out May 15 09:44:41 bro dhcpcd[564]: timed out May 15 09:44:41 bro sh[517]: dhcpcd exited May 15 09:44:41 bro dhcpcd[564]: dhcpcd exited May 15 09:44:41 bro sh[517]: ifup: failed to bring up eth0 May 15 09:44:41 bro systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 15 09:44:41 bro systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 15 09:44:42 bro systemd[1]: systemd-hostnamed.service: Succeeded. May 15 09:44:42 bro kernel: cryptd: max_cpu_qlen set to 1000 May 15 09:44:43 bro sudo[1174]: pam_unix(sudo:session): session closed for user root May 15 09:44:43 bro volumio[992]: info: Completed loading Core Plugins May 15 09:44:43 bro volumio[992]: info: Preparing to generate the ALSA configuration file May 15 09:44:43 bro volumio[992]: info: Asound.conf file unchanged, so no further update is needed May 15 09:44:43 bro volumio[992]: info: Output device has changed, restarting MPD May 15 09:44:43 bro volumio[992]: info: Output device has changed, restarting Shairport Sync May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 09:44:43 bro volumio[992]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 15 09:44:43 bro volumio[992]: info: ___________ START PLUGINS ___________ May 15 09:44:43 bro volumio[992]: info: ControllerMpd::onStart: Initializing MPD May 15 09:44:43 bro volumio[992]: info: Creating MPD Configuration file May 15 09:44:43 bro sudo[1283]: volumio : unable to resolve host bro May 15 09:44:43 bro sudo[1283]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:43 bro sudo[1283]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 15 09:44:43 bro sudo[1283]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:43 bro sudo[1283]: pam_unix(sudo:session): session closed for user root May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 15 09:44:43 bro volumio[992]: info: [1747295083699] CoreMusicLibrary::Adding element Medienserver May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 09:44:43 bro sudo[1285]: volumio : unable to resolve host bro May 15 09:44:43 bro sudo[1285]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:43 bro sudo[1285]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 15 09:44:43 bro sudo[1285]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 09:44:43 bro systemd[1]: Stopping Music Player Daemon... May 15 09:44:43 bro volumio[992]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 09:44:43 bro sudo[1291]: volumio : unable to resolve host bro May 15 09:44:43 bro sudo[1291]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:43 bro sudo[1293]: volumio : unable to resolve host bro May 15 09:44:43 bro sudo[1293]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:43 bro sudo[1291]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 15 09:44:43 bro sudo[1293]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 15 09:44:43 bro sudo[1291]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:43 bro sudo[1293]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:43 bro sudo[1291]: pam_unix(sudo:session): session closed for user root May 15 09:44:43 bro volumio[992]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 15 09:44:43 bro volumio[992]: info: [1747295083800] CoreMusicLibrary::Adding element Last_100 May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 15 09:44:43 bro volumio[992]: info: [1747295083802] CoreMusicLibrary::Adding element Webradio May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 15 09:44:43 bro volumio[992]: info: Initializing BBC Radios May 15 09:44:43 bro systemd[1]: mpd.service: Succeeded. May 15 09:44:43 bro systemd[1]: Stopped Music Player Daemon. May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 09:44:43 bro volumio[992]: info: Creating Spotify config file May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:43 bro systemd[1]: Starting Music Player Daemon... May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 15 09:44:43 bro volumio[992]: info: [1747295083937] CoreMusicLibrary::Adding element 80s80s Radio May 15 09:44:43 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 09:44:43 bro volumio[992]: Cannot find translation for source 80s80s Radio May 15 09:44:43 bro volumio[992]: info: Volumio Calling Home May 15 09:44:44 bro sudo[1315]: volumio : unable to resolve host bro May 15 09:44:44 bro sudo[1315]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:44 bro sudo[1315]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service May 15 09:44:44 bro sudo[1315]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:44 bro sudo[1306]: root : unable to resolve host bro May 15 09:44:44 bro sudo[1306]: root : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:44 bro sudo[1306]: sudo: unable to resolve host bro: System error May 15 09:44:44 bro sudo[1306]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 15 09:44:44 bro sudo[1306]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:44 bro systemd[1]: Started RoonBridge. May 15 09:44:44 bro sudo[1306]: pam_unix(sudo:session): session closed for user root May 15 09:44:44 bro volumio[992]: info: MPD Permissions set May 15 09:44:44 bro volumio[992]: info: MPD Permissions set May 15 09:44:44 bro volumio[992]: info: Spotify config file written May 15 09:44:44 bro sudo[1315]: pam_unix(sudo:session): session closed for user root May 15 09:44:44 bro volumio[992]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro sudo[1328]: volumio : unable to resolve host bro May 15 09:44:44 bro sudo[1328]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:44 bro sudo[1328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 15 09:44:44 bro sudo[1328]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 09:44:44 bro volumio[992]: info: No need to fix Spotify hosts May 15 09:44:44 bro systemd[1]: Started go-librespot Daemon. May 15 09:44:44 bro go-librespot[1338]: go-librespot daemon starting... May 15 09:44:44 bro sudo[1328]: pam_unix(sudo:session): session closed for user root May 15 09:44:44 bro volumio[992]: info: Volumio called home May 15 09:44:44 bro volumio[992]: info: Starting Shairport Sync May 15 09:44:44 bro volumio[992]: info: Starting Shairport Sync May 15 09:44:44 bro volumio[992]: info: Starting Shairport Sync May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::volumioGetState May 15 09:44:44 bro volumio[992]: info: CorePlayQueue::getTrack 0 May 15 09:44:44 bro sudo[1344]: volumio : unable to resolve host bro May 15 09:44:44 bro sudo[1344]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:44 bro sudo[1344]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 15 09:44:44 bro sudo[1346]: volumio : unable to resolve host bro May 15 09:44:44 bro sudo[1346]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:44 bro sudo[1344]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:44 bro sudo[1346]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 15 09:44:44 bro sudo[1346]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:44 bro systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 15 09:44:44 bro systemd[1]: shairport-sync.service: Succeeded. May 15 09:44:44 bro systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 15 09:44:44 bro sudo[1349]: volumio : unable to resolve host bro May 15 09:44:44 bro sudo[1349]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:44 bro sudo[1349]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 15 09:44:44 bro sudo[1349]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:44 bro systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 15 09:44:44 bro sudo[1344]: pam_unix(sudo:session): session closed for user root May 15 09:44:44 bro systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 15 09:44:44 bro systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 15 09:44:44 bro systemd[1]: shairport-sync.service: Succeeded. May 15 09:44:44 bro systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 15 09:44:44 bro volumio[992]: info: Shairport-Sync Started May 15 09:44:44 bro volumio[992]: Error adding Membership: Error: addMembership EINVAL May 15 09:44:44 bro systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 15 09:44:44 bro volumio[992]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 15 09:44:44 bro volumio[992]: SPOTIFY: BQDWMw86H2x_tmVa099hR_kyXnejGqJaAh-c37XKmp0vQHp_oOCY4h5p6YG0_3ohbgwpFQynU6jZorqqjAHLbnteUT7HI0uRAS6rGCQcFNoJGfn5870qE-tCztDv2phyKCgNB4M_9jchdm8lon4efmnK9FhjKnkyPUVkdKURTmxwrc62h257mp0usNzXLL2OMs8cbDbwOg4h2h4FSSaeT3f-z62iafQtf64obi3pRTzT-wpJIvPcgND2-Pk9vpIaedWezoy5-Ao_ZnziN3SrVdxM May 15 09:44:44 bro volumio[992]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 15 09:44:44 bro sudo[1349]: pam_unix(sudo:session): session closed for user root May 15 09:44:44 bro sudo[1346]: pam_unix(sudo:session): session closed for user root May 15 09:44:44 bro volumio[992]: info: New Spotify access token = BQDWMw86H2x_tmVa099hR_kyXnejGqJaAh-c37XKmp0vQHp_oOCY4h5p6YG0_3ohbgwpFQynU6jZorqqjAHLbnteUT7HI0uRAS6rGCQcFNoJGfn5870qE-tCztDv2phyKCgNB4M_9jchdm8lon4efmnK9FhjKnkyPUVkdKURTmxwrc62h257mp0usNzXLL2OMs8cbDbwOg4h2h4FSSaeT3f-z62iafQtf64obi3pRTzT-wpJIvPcgND2-Pk9vpIaedWezoy5-Ao_ZnziN3SrVdxM May 15 09:44:44 bro volumio[992]: info: Spotify credentials grant success - running version from March 24, 2019 May 15 09:44:44 bro volumio[992]: info: Shairport-Sync Started May 15 09:44:44 bro volumio[992]: info: Shairport-Sync Started May 15 09:44:44 bro volumio[992]: SPOTIFY: User informations: {"country":"DE","display_name":"itakaboy","email":"rctuner22@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/itakaboy"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/itakaboy","id":"itakaboy","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85d255e19b73bfe340de911c78","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82d255e19b73bfe340de911c78","width":64}],"product":"premium","type":"user","uri":"spotify:user:itakaboy"} May 15 09:44:44 bro volumio[992]: info: Spotify Successfully logged in May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 15 09:44:44 bro volumio[992]: info: [1747295084691] CoreMusicLibrary::Adding element Spotify May 15 09:44:44 bro volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 09:44:44 bro volumio[992]: Cannot find translation for source 80s80s Radio May 15 09:44:44 bro volumio[992]: Cannot find translation for source Spotify May 15 09:44:44 bro go-librespot[1338]: time="2025-05-15T09:44:44+02:00" level=info msg="running go-librespot 0.2.0" May 15 09:44:44 bro go-librespot[1338]: time="2025-05-15T09:44:44+02:00" level=debug msg="app state loaded" May 15 09:44:44 bro go-librespot[1338]: time="2025-05-15T09:44:44+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 15 09:44:44 bro mpd[1322]: May 15 09:44 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 15 09:44:44 bro systemd[1]: Started Music Player Daemon. May 15 09:44:44 bro sudo[1285]: pam_unix(sudo:session): session closed for user root May 15 09:44:44 bro sudo[1293]: pam_unix(sudo:session): session closed for user root May 15 09:44:44 bro volumio[992]: info: Completed starting Core Plugins May 15 09:44:44 bro volumio[992]: info: ------------------------------------------- May 15 09:44:44 bro volumio[992]: info: ----- MyVolumio plugins startup ---- May 15 09:44:44 bro volumio[992]: info: ------------------------------------------- May 15 09:44:44 bro volumio[992]: info: [MyVolumio PluginManager] Fetching plans data.... May 15 09:44:44 bro volumio[992]: error: MPD error: The expression evaluated to a falsy value: May 15 09:44:44 bro volumio[992]: assert.ok(self.idling) May 15 09:44:44 bro volumio[992]: error: The expression evaluated to a falsy value: May 15 09:44:44 bro volumio[992]: assert.ok(self.idling) May 15 09:44:44 bro volumio[992]: error: updateQueue error: null May 15 09:44:44 bro volumio[992]: info: MPD running with PID1322 May 15 09:44:44 bro volumio[992]: ,establishing connection May 15 09:44:44 bro volumio[992]: error: updateQueue error: null May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=info msg="zeroconf server listening on port 34879" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="obtained new client token: AAB1AnyEuORIzo57/GBlq/0D2FnV4FXBqdVupg9/gD9c58yO8RoRsbGqQCMkLhMPm7fOxLy5v/mYWD7a4EcTZfMWAfc9/iLv6JVA34p2ftnBduTa528EBDuUDE2uAOQXL9Owdf9sfet3rnJkUOzymrYi/FRB3pzDGOVAiBeSHjZLWRNibo2Juo1l9jgp4MyA6fdiUCoaxUsjqw3K9Lb29F6WDGfh27QMAoDFydSHC8DFKuYF18Jqft1FEA==" May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.008 Warn: get lock file path: /tmp/.rnbgem0- May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="completed keyexchange" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="completed challenge" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=info msg="authenticated AP as itakaboy" May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.326 Trace: [childprocess] using unix child process May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.377 Debug: PathForResource, filename: ../.update May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=info msg="authenticated Login5 as itakaboy" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="initializing zeroconf session, username: itakaboy" May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.438 Debug: PathForResource, candidate: /data/plugins/music_service/RoonBridge/RoonBridge/Bridge/../.update May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.444 Debug: PathForResource, filename: RAATServer May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.444 Debug: PathForResource, candidate: /data/plugins/music_service/RoonBridge/RoonBridge/Bridge/RAATServer May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.445 Debug: PathForResource, filename: RoonBridgeHelper May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.445 Debug: PathForResource, candidate: /data/plugins/music_service/RoonBridge/RoonBridge/Bridge/RoonBridgeHelper May 15 09:44:45 bro RoonBridge[1321]: Initializing May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.476 Info: Starting /data/plugins/music_service/RoonBridge/RoonBridge/Bridge/RoonBridgeHelper May 15 09:44:45 bro RoonBridge[1321]: 00:00:00.506 Info: ConnectOrStartAndWaitForExit RAATServer, path: /data/plugins/music_service/RoonBridge/RoonBridge/Bridge/RAATServer May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="dealer connection opened" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=trace msg="starting accesspoint recv loop" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=trace msg="starting dealer recv loop" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=trace msg="received accesspoint ping" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=debug msg="received connection id: Yzk4ODBjNTktNDg1My00ZTlmLWJmOTEtMzQ4Zjk1MTdjMTIxK2RlYWxlcit0Y3A6Ly8wYWNhNTkxOS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMjFCQzlFRUM0NUY3QjEwQUQxRDM2Q0NCRDk1QTRGNEZFRjJBMzM1ODFENDdBMjZBNTc0Rjc0NjdFQzNDNzJDNQ==" May 15 09:44:45 bro go-librespot[1338]: time="2025-05-15T09:44:45+02:00" level=trace msg="received accesspoint pong ack" May 15 09:44:45 bro RoonBridge[1321]: Not Running (.o) May 15 09:44:45 bro sudo[1401]: volumio : unable to resolve host bro May 15 09:44:45 bro sudo[1401]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:46 bro sudo[1401]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 15 09:44:46 bro sudo[1401]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:46 bro sudo[1401]: pam_unix(sudo:session): session closed for user root May 15 09:44:46 bro sudo[1403]: volumio : unable to resolve host bro May 15 09:44:46 bro sudo[1403]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:46 bro sudo[1403]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 15 09:44:46 bro sudo[1403]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:46 bro sudo[1403]: pam_unix(sudo:session): session closed for user root May 15 09:44:46 bro go-librespot[1338]: time="2025-05-15T09:44:46+02:00" level=debug msg="put connect state because NEW_DEVICE" May 15 09:44:46 bro sudo[1405]: volumio : unable to resolve host bro May 15 09:44:46 bro sudo[1405]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:46 bro sudo[1405]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 15 09:44:46 bro sudo[1405]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 09:44:46 bro RoonBridge[1321]: Running May 15 09:44:46 bro systemd[1]: Started UPnP Renderer front-end to MPD. May 15 09:44:46 bro sudo[1405]: pam_unix(sudo:session): session closed for user root May 15 09:44:46 bro volumio[992]: info: Upmpdcli Daemon Started May 15 09:44:46 bro volumio[1409]: Generating RSA private key, 4096 bit long modulus (2 primes) May 15 09:44:46 bro RoonBridge[1321]: 00:00:00.022 Warn: get lock file path: /tmp/.rnbhgem0- May 15 09:44:47 bro volumio[1409]: .......++++ May 15 09:44:47 bro volumio[992]: info: go-librespot daemon successfully initialized May 15 09:44:47 bro go-librespot[1338]: time="2025-05-15T09:44:47+02:00" level=debug msg="handling transfer player command from 07fdc4cc09b01f0a920cbb5e59cbba7d3e2a8553" May 15 09:44:47 bro go-librespot[1338]: time="2025-05-15T09:44:47+02:00" level=debug msg="resolved context of track" uri="spotify:station:artist:3JsMj0DEzyWc0VDlHuy9Bx" May 15 09:44:47 bro go-librespot[1338]: time="2025-05-15T09:44:47+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:artist:3JsMj0DEzyWc0VDlHuy9Bx" May 15 09:44:47 bro go-librespot[1338]: time="2025-05-15T09:44:47+02:00" level=warning msg="failed seeking to track in context spotify:station:artist:3JsMj0DEzyWc0VDlHuy9Bx" error="failed fetching tracks for seek: failed moving to next index 50 (page 1): failed fetching next page: invalid status code from page at radio-apollo/v3/tracks/spotify:station:artist:3JsMj0DEzyWc0VDlHuy9Bx?salt=242496&autoplay=false&count=50&isVideo=false&prev_tracks=26TsScuJSlqwZyaoWG2l7u,0r5Ju8WyodpXBHmg3f4zYf,2kKNeapwCHUUvMhmAOGce6,4KFM3A5QF2IMcc6nHsu3Wp,3kyW3qviTr2dIyvqa1lEWC,2wnsBaxrmkthIFAm6vqCuX,3AUpYeScJOpYf8psTIz62l,7n3WO6ESKS1uCI9fgkGs66,7257drAN3eTtaaUUPw95B3,5Xhqe9xu6bKRSqLj1mS1SB,2viraKhy1hIBDCWYA8jtPs,5z4ljpMLi1LTF8UG9P53fH,1wrT33b6HuKlpk9ziscEUY,08onVqQ8YicJ98Ycm1qoLf,4VbOIkKqt0gkZpC75oKSxS,4mn2kNTqiGLwaUR8JdhJ1l,089NMLhXz421ohFN55A3yo,4IU1RL4BKvFyXtbTwaHAvW,7L3b6iaVhDVjfo52Hbvh9Z,4sCCZW0ezEPAexAidFsoVm,4YMQXzscifAREG0a7KNGhB,4GlAs0yVBjKbdpCTFlM90p,10BQIOZ8dhGwOOGBVA97qz,5dXED6MP1v1qghkaniirb1,7fYKKFD0jiSlMDgG9IUs1q,0PbFXpNL2f34qFtJrR3OSW,67oyFnjJnn78fZP9KjeZx0,44JITu0xanJn3TLMQZJw0G,2Pzhx26KqgTTKnko0uC7F7,3fbnbn6A5O5RNb08tlUEgd,0vlCOzte4bru0gK74lfUIJ,6fnachl7fIn5dqIjakfJ57,0NI9wGowTO80hVs3l6wa0i,6ek9SiEj5a65WIs2EV7qiM,4vGwwMIIvFHtm4KX0rqF0U,05vL56xSoxthM0r7IfcQjo,4a5pNRjwmzYQuEY1E7O6pj,26QKxvjlCo2fSd3T4c8Zpb,4tSZr210OTY6upjNYfEYUI,2OgVsp77En2nju8pnCieVU,1AwNt4KWb7hF7OaVI6CwCN,0OtgQMnnZL5KVjpABf6SdR,37Tmv4NnfQeb0ZgUC4fOJj,12Sv9ZrMuM4ZzaWIZUTN6K,0YZ3J8xzGwLOg4yEgST1YK,5hrsqusQlSqlWpvtjJpxPq,7AW4T7G3e8VsZ8D7jV1hMr,5qdlMWYpCtJFsHey3rXYms,4ntaCVtTclqT43krz9n3Z9,400ZJAUFuEuIGXhr7ie4xf&minimal=true: 502" uri="spotify:station:artist:3JsMj0DEzyWc0VDlHuy9Bx" May 15 09:44:47 bro go-librespot[1338]: time="2025-05-15T09:44:47+02:00" level=debug msg="loading track (paused: true, position: 244675ms)" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:47 bro go-librespot[1338]: time="2025-05-15T09:44:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 15 09:44:47 bro go-librespot[1338]: time="2025-05-15T09:44:47+02:00" level=trace msg="emitting websocket event: will_play" May 15 09:44:48 bro go-librespot[1338]: time="2025-05-15T09:44:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 15 09:44:48 bro go-librespot[1338]: time="2025-05-15T09:44:48+02:00" level=debug msg="selected format OGG_VORBIS_320 (499f745204271fcc23ffeb56c1dd4a628ec49808)" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:48 bro go-librespot[1338]: time="2025-05-15T09:44:48+02:00" level=debug msg="requested aes key for file 499f745204271fcc23ffeb56c1dd4a628ec49808, gid: 26TsScuJSlqwZyaoWG2l7u" May 15 09:44:48 bro go-librespot[1338]: time="2025-05-15T09:44:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1658" May 15 09:44:48 bro volumio[1409]: ...........++++ May 15 09:44:48 bro volumio[1409]: e is 65537 (0x010001) May 15 09:44:48 bro volumio[1409]: writing RSA key May 15 09:44:48 bro go-librespot[1338]: time="2025-05-15T09:44:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1272" May 15 09:44:48 bro go-librespot[1338]: time="2025-05-15T09:44:48+02:00" level=debug msg="fetched first chunk of 21, total size is 10537688 bytes" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:48 bro go-librespot[1338]: time="2025-05-15T09:44:48+02:00" level=debug msg="fetched chunk 20/20, size: 51928" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:48 bro go-librespot[1338]: time="2025-05-15T09:44:48+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:48 bro volumio-remote-updater[613]: [2025-05-15 09:44:48] [connect] Successful connection May 15 09:44:48 bro volumio-remote-updater[613]: [2025-05-15 09:44:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1747295088 101 May 15 09:44:48 bro volumio[992]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 2 May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="fetched chunk 19/20, size: 524288" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=trace msg="seek to 244675ms (diff: 117ms, samples: 10790167, bytes: 10451008)" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="created new output device" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=info msg="loaded track \"The Logical Song - Live At Pavillon de Paris/1979\" (paused: true, position: 244675ms, duration: 245866ms, prefetched: false)" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=trace msg="emitting websocket event: metadata" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=trace msg="emitting websocket event: active" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="sending successful reply for dealer request" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 15 09:44:49 bro go-librespot[1338]: time="2025-05-15T09:44:49+02:00" level=trace msg="emitting websocket event: paused" May 15 09:44:49 bro volumio[992]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="handling resume player command from 07fdc4cc09b01f0a920cbb5e59cbba7d3e2a8553" May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=trace msg="seek to 244675ms (diff: 117ms, samples: 10790167, bytes: 10451008)" uri="spotify:track:26TsScuJSlqwZyaoWG2l7u" May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+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 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="resume track at 244558ms" May 15 09:44:50 bro volumio[992]: info: Initializing connection to go-librespot Websocket May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="new websocket client" May 15 09:44:50 bro volumio[992]: info: Connection to go-librespot Websocket established May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="sending successful reply for dealer request" May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="prefetching next track" uri="spotify:track:0r5Ju8WyodpXBHmg3f4zYf" May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="selected format OGG_VORBIS_320 (1a9daea3f9d31fd265cdaaee460d3b3a46f5993c)" uri="spotify:track:0r5Ju8WyodpXBHmg3f4zYf" May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="requested aes key for file 1a9daea3f9d31fd265cdaaee460d3b3a46f5993c, gid: 0r5Ju8WyodpXBHmg3f4zYf" May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 15 09:44:50 bro go-librespot[1338]: time="2025-05-15T09:44:50+02:00" level=trace msg="emitting websocket event: playing" May 15 09:44:50 bro volumio[992]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:26TsScuJSlqwZyaoWG2l7u","play_origin":""}} May 15 09:44:50 bro volumio[992]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 15 09:44:50 bro volumio[992]: TypeError: Cannot read property 'service' of undefined May 15 09:44:50 bro volumio[992]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) May 15 09:44:50 bro volumio[992]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) May 15 09:44:50 bro volumio[992]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) May 15 09:44:50 bro volumio[992]: at WebSocket.emit (events.js:315:20) May 15 09:44:50 bro volumio[992]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 15 09:44:50 bro volumio[992]: at Receiver.emit (events.js:315:20) May 15 09:44:50 bro volumio[992]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 15 09:44:50 bro volumio[992]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 15 09:44:50 bro volumio[992]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 15 09:44:50 bro volumio[992]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 15 09:44:50 bro volumio[992]: at writeOrBuffer (internal/streams/writable.js:358:12) May 15 09:44:50 bro volumio[992]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 15 09:44:50 bro volumio[992]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 15 09:44:50 bro volumio[992]: at Socket.emit (events.js:315:20) May 15 09:44:50 bro volumio[992]: at addChunk (internal/streams/readable.js:309:12) May 15 09:44:50 bro volumio[992]: at readableAddChunk (internal/streams/readable.js:284:9) May 15 09:44:50 bro volumio[992]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 15 09:44:50 bro sudo[1498]: volumio : unable to resolve host bro May 15 09:44:50 bro sudo[1498]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 09:44:50 bro sudo[1498]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-15 09:43 May 15 09:44:50 bro sudo[1498]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"