-- Logs begin at Wed 2025-05-07 22:03:39 CEST, end at Wed 2025-05-07 22:05:22 CEST. -- May 07 22:04:00 musicbox wireless.js[592]: trying... May 07 22:04:00 musicbox sudo[927]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 07 22:04:00 musicbox sudo[927]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:00 musicbox sudo[927]: pam_unix(sudo:session): session closed for user root May 07 22:04:01 musicbox wpa_supplicant[893]: wlan0: Trying to associate with SSID 'TrauschNet Privat' May 07 22:04:01 musicbox dhcpcd[905]: wlan0: carrier acquired May 07 22:04:01 musicbox dhcpcd[905]: wlan0: connected to Access Point `TrauschNet Privat' May 07 22:04:01 musicbox wpa_supplicant[893]: wlan0: Associated with 0c:72:74:e6:49:57 May 07 22:04:01 musicbox wpa_supplicant[893]: wlan0: CTRL-EVENT-CONNECTED - Connection to 0c:72:74:e6:49:57 completed [id=0 id_str=] May 07 22:04:01 musicbox wpa_supplicant[893]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 May 07 22:04:01 musicbox wpa_supplicant[893]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE May 07 22:04:01 musicbox dhcpcd[905]: DUID 00:01:00:01:2c:c5:41:c9:b8:27:eb:6e:28:f1 May 07 22:04:01 musicbox dhcpcd[905]: wlan0: IAID eb:6e:28:f1 May 07 22:04:01 musicbox dhcpcd[905]: wlan0: adding address fe80::316a:333e:60f6:d02b May 07 22:04:01 musicbox dhcpcd[905]: ipv6_addaddr1: Permission denied May 07 22:04:01 musicbox dhcpcd[905]: wlan0: carrier lost May 07 22:04:01 musicbox dhcpcd[905]: wlan0: carrier acquired May 07 22:04:01 musicbox dhcpcd[905]: wlan0: IAID eb:6e:28:f1 May 07 22:04:01 musicbox volumio-time-update[599]: volumio-time-update-util: Fetching time from Volumio... May 07 22:04:01 musicbox volumio-time-update[599]: volumio-time-update-util: Date not found in response May 07 22:04:01 musicbox volumio-time-update[599]: volumio-time-update-util: Retrying in 5 seconds... May 07 22:04:01 musicbox dhcpcd[905]: wlan0: soliciting an IPv6 router May 07 22:04:01 musicbox dhcpcd[905]: wlan0: rebinding lease of 192.168.178.119 May 07 22:04:01 musicbox wireless.js[592]: trying... May 07 22:04:01 musicbox dhcpcd[905]: wlan0: probing address 192.168.178.119/24 May 07 22:04:01 musicbox sudo[948]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 07 22:04:01 musicbox sudo[948]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:01 musicbox sudo[948]: pam_unix(sudo:session): session closed for user root May 07 22:04:02 musicbox wireless.js[592]: trying... May 07 22:04:02 musicbox sudo[951]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 07 22:04:02 musicbox sudo[951]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:02 musicbox sudo[951]: pam_unix(sudo:session): session closed for user root May 07 22:04:03 musicbox wireless.js[592]: trying... May 07 22:04:03 musicbox sudo[954]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 07 22:04:03 musicbox sudo[954]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:03 musicbox sudo[954]: pam_unix(sudo:session): session closed for user root May 07 22:04:04 musicbox wireless.js[592]: trying... May 07 22:04:04 musicbox sudo[957]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 07 22:04:04 musicbox sudo[957]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:04 musicbox sudo[957]: pam_unix(sudo:session): session closed for user root May 07 22:04:05 musicbox wireless.js[592]: trying... May 07 22:04:05 musicbox sudo[960]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 07 22:04:05 musicbox sudo[960]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:05 musicbox sudo[960]: pam_unix(sudo:session): session closed for user root May 07 22:04:06 musicbox volumio-time-update[599]: volumio-time-update-util: Fetching time from Volumio... May 07 22:04:06 musicbox volumio-time-update[599]: volumio-time-update-util: Date not found in response May 07 22:04:06 musicbox volumio-time-update[599]: volumio-time-update-util: Retrying in 5 seconds... May 07 22:04:06 musicbox wireless.js[592]: trying... May 07 22:04:06 musicbox sudo[968]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 07 22:04:06 musicbox sudo[968]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:06 musicbox sudo[968]: pam_unix(sudo:session): session closed for user root May 07 22:04:07 musicbox dhcpcd[905]: wlan0: leased 192.168.178.119 for 864000 seconds May 07 22:04:07 musicbox avahi-daemon[615]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.119. May 07 22:04:07 musicbox avahi-daemon[615]: New relevant interface wlan0.IPv4 for mDNS. May 07 22:04:07 musicbox avahi-daemon[615]: Registering new address record for 192.168.178.119 on wlan0.IPv4. May 07 22:04:07 musicbox dhcpcd[905]: wlan0: adding route to 192.168.178.0/24 May 07 22:04:07 musicbox dhcpcd[905]: wlan0: adding default route via 192.168.178.1 May 07 22:04:07 musicbox wireless.js[592]: trying... May 07 22:04:07 musicbox sudo[992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 07 22:04:07 musicbox sudo[992]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:07 musicbox sudo[992]: pam_unix(sudo:session): session closed for user root May 07 22:04:07 musicbox wireless.js[592]: Connected to: ----TrauschNet Privat May 07 22:04:07 musicbox wireless.js[592]: ---- May 07 22:04:07 musicbox sudo[995]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 07 22:04:07 musicbox sudo[995]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:07 musicbox sudo[995]: pam_unix(sudo:session): session closed for user root May 07 22:04:07 musicbox wireless.js[592]: ... joined AP, wlan0 IPv4 is 192.168.178.119, ipV6 is undefined May 07 22:04:07 musicbox wireless.js[592]: It's done! AP May 07 22:04:08 musicbox systemd[1]: Started Wireless Services. May 07 22:04:08 musicbox kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 07 22:04:08 musicbox systemd[1]: Started Volumio Backend Module. May 07 22:04:08 musicbox systemd[1]: Started Volumio Cpu Tweaker. May 07 22:04:08 musicbox volumio-cpu-tweak[1001]: Setting RT Priority for mpd May 07 22:04:08 musicbox volumio-cpu-tweak[1001]: Setting MPD Affinity May 07 22:04:08 musicbox volumio-cpu-tweak[1001]: pid 798's current affinity mask: f May 07 22:04:08 musicbox volumio-cpu-tweak[1001]: pid 798's new affinity mask: 3 May 07 22:04:08 musicbox volumio-cpu-tweak[1001]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input May 07 22:04:08 musicbox volumio-cpu-tweak[1001]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance May 07 22:04:08 musicbox systemd[1]: volumio_cpu_tweak.service: Succeeded. May 07 22:04:08 musicbox volumio-remote-updater[590]: [2025-05-07 22:04:08] [info] asio async_connect error: system:111 (Connection refused) May 07 22:04:08 musicbox volumio-remote-updater[590]: [2025-05-07 22:04:08] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 07 22:04:08 musicbox volumio-remote-updater[590]: [2025-05-07 22:04:08] [error] handle_connect error: Underlying Transport Error May 07 22:04:08 musicbox ntpd[747]: Listen normally on 3 wlan0 192.168.178.119:123 May 07 22:04:08 musicbox ntpd[747]: new interface(s) found: waking up resolver May 07 22:04:09 musicbox nmbd[746]: [2025/05/07 22:04:09.720114, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 07 22:04:09 musicbox systemd[1]: Started Samba NMB Daemon. May 07 22:04:09 musicbox nmbd[746]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 07 22:04:09 musicbox systemd[1]: Starting Samba Winbind Daemon... May 07 22:04:10 musicbox winbindd[1017]: [2025/05/07 22:04:10.364229, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 07 22:04:10 musicbox winbindd[1017]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 07 22:04:10 musicbox winbindd[1017]: [2025/05/07 22:04:10.394253, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 07 22:04:10 musicbox systemd[1]: Started Samba Winbind Daemon. May 07 22:04:10 musicbox winbindd[1017]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 07 22:04:10 musicbox systemd[1]: Starting Samba SMB Daemon... May 07 22:04:11 musicbox smbd[1022]: [2025/05/07 22:04:11.419918, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 07 22:04:11 musicbox systemd[1]: Started Samba SMB Daemon. May 07 22:04:11 musicbox smbd[1022]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 07 22:04:11 musicbox volumio-time-update[599]: volumio-time-update-util: Fetching time from Volumio... May 07 22:04:11 musicbox volumio-time-update[599]: volumio-time-update-util: Setting system time to: 2025-05-07 22:04:45 May 07 22:04:11 musicbox sudo[1035]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-05-07 22:04:45 May 07 22:04:11 musicbox sudo[1035]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:11 musicbox dbus-daemon[608]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.10' (uid=0 pid=1036 comm="timedatectl set-time 2025-05-07 22:04:45 ") May 07 22:04:11 musicbox systemd[1]: Starting Time & Date Service... May 07 22:04:11 musicbox systemd[1]: systemd-fsckd.service: Succeeded. May 07 22:04:12 musicbox dbus-daemon[608]: [system] Successfully activated service 'org.freedesktop.timedate1' May 07 22:04:12 musicbox systemd[1]: Started Time & Date Service. May 07 22:04:45 musicbox systemd-timedated[1037]: Changed local time to Wed May 7 22:04:45 2025 May 07 22:04:45 musicbox sudo[1035]: pam_unix(sudo:session): session closed for user root May 07 22:04:45 musicbox volumio-time-update[599]: volumio-time-update-util: System time updated successfully. May 07 22:04:45 musicbox systemd[1]: Started Volumio Time Update Utility. May 07 22:04:45 musicbox systemd[1]: Reached target Multi-User System. May 07 22:04:45 musicbox systemd[1]: Reached target Graphical Interface. May 07 22:04:45 musicbox systemd[1]: Starting Update UTMP about System Runlevel Changes... May 07 22:04:45 musicbox systemd[1]: Starting Shutdown Raspberry Pi after 60 minutes... May 07 22:04:45 musicbox shutdown[1039]: Shutdown scheduled for Wed 2025-05-07 23:03:45 CEST, use 'shutdown -c' to cancel. May 07 22:04:45 musicbox systemd[1]: Started Shutdown Raspberry Pi after 60 minutes. May 07 22:04:45 musicbox systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 07 22:04:45 musicbox systemd[1]: Started Update UTMP about System Runlevel Changes. May 07 22:04:45 musicbox systemd[1]: Startup finished in 15.768s (kernel) + 35.692s (userspace) = 51.460s. May 07 22:04:45 musicbox volumio[1000]: info: ------------------------------------------- May 07 22:04:45 musicbox volumio[1000]: info: ----- Volumio3 ---- May 07 22:04:45 musicbox volumio[1000]: info: ------------------------------------------- May 07 22:04:45 musicbox volumio[1000]: info: ----- System startup ---- May 07 22:04:45 musicbox volumio[1000]: info: ------------------------------------------- May 07 22:04:47 musicbox avahi-daemon[615]: Host name conflict, retrying with musicbox-2 May 07 22:04:47 musicbox avahi-daemon[615]: Registering new address record for 192.168.178.119 on wlan0.IPv4. May 07 22:04:47 musicbox volumio[1000]: info: MYVOLUMIO Environment detected May 07 22:04:48 musicbox volumio[1000]: info: Plugin folders cleanup May 07 22:04:48 musicbox volumio[1000]: info: Scanning into folder /volumio/app/plugins/ May 07 22:04:48 musicbox volumio[1000]: info: Scanning category audio_interface May 07 22:04:48 musicbox volumio[1000]: info: Scanning category miscellanea May 07 22:04:48 musicbox volumio[1000]: info: Scanning category music_service May 07 22:04:48 musicbox volumio[1000]: info: Scanning category plugins.json May 07 22:04:48 musicbox volumio[1000]: info: Scanning category system_controller May 07 22:04:48 musicbox volumio[1000]: info: Scanning category user_interface May 07 22:04:48 musicbox volumio[1000]: info: Scanning into folder /data/plugins/ May 07 22:04:48 musicbox volumio[1000]: info: Scanning category music_service May 07 22:04:48 musicbox volumio[1000]: info: Scanning category system_controller May 07 22:04:48 musicbox volumio[1000]: info: Scanning category system_hardware May 07 22:04:48 musicbox volumio[1000]: info: Plugin folders cleanup completed May 07 22:04:48 musicbox volumio[1000]: info: ------------------------------------------- May 07 22:04:48 musicbox volumio[1000]: info: ----- Core plugins startup ---- May 07 22:04:48 musicbox volumio[1000]: info: ------------------------------------------- May 07 22:04:48 musicbox volumio[1000]: info: Loading plugins from folder /volumio/app/plugins/ May 07 22:04:48 musicbox volumio[1000]: info: Adding plugin upnp to MyMusic Plugins May 07 22:04:48 musicbox volumio[1000]: info: Adding plugin airplay_emulation to MyMusic Plugins May 07 22:04:48 musicbox volumio[1000]: info: Adding plugin upnp_browser to MyMusic Plugins May 07 22:04:48 musicbox volumio[1000]: info: Loading plugins from folder /data/plugins/ May 07 22:04:48 musicbox volumio[1000]: info: Loading plugin "system"... May 07 22:04:48 musicbox volumio[1000]: info: Loading plugin "appearance"... May 07 22:04:48 musicbox avahi-daemon[615]: Server startup complete. Host name is musicbox-2.local. Local service cookie is 1476206348. May 07 22:04:49 musicbox sh[570]: timed out May 07 22:04:49 musicbox dhcpcd[589]: timed out May 07 22:04:49 musicbox sh[570]: dhcpcd exited May 07 22:04:49 musicbox dhcpcd[589]: dhcpcd exited May 07 22:04:49 musicbox sh[570]: ifup: failed to bring up eth0 May 07 22:04:49 musicbox systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 07 22:04:49 musicbox systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 07 22:04:49 musicbox avahi-daemon[615]: Service "MusicBox" (/services/volumio.service) successfully established. May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "network"... May 07 22:04:51 musicbox volumio[1000]: info: Refreshing Cached IP Addresses May 07 22:04:51 musicbox sudo[1058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 07 22:04:51 musicbox sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:51 musicbox sudo[1060]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 07 22:04:51 musicbox sudo[1060]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:51 musicbox sudo[1058]: pam_unix(sudo:session): session closed for user root May 07 22:04:51 musicbox sudo[1060]: pam_unix(sudo:session): session closed for user root May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "services"... May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "alsa_controller"... May 07 22:04:51 musicbox sudo[1072]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 07 22:04:51 musicbox sudo[1072]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:51 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "wizard"... May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "networkfs"... May 07 22:04:51 musicbox volumio-remote-updater[590]: [2025-05-07 22:04:51] [connect] Successful connection May 07 22:04:51 musicbox systemd[1]: systemd-hostnamed.service: Succeeded. May 07 22:04:51 musicbox volumio[1000]: info: Starting Udev Watcher for removable devices May 07 22:04:51 musicbox sudo[1088]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=lukas,password=Pia0815@2612,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //se-se01/internal/music /mnt/NAS/Musik May 07 22:04:51 musicbox sudo[1088]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:04:51 musicbox volumio[1000]: info: Ignoring mount for partition: boot May 07 22:04:51 musicbox volumio[1000]: info: Ignoring mount for partition: volumio May 07 22:04:51 musicbox volumio[1000]: info: Ignoring mount for partition: volumio_data May 07 22:04:51 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "volumio_command_line_client"... May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "upnp"... May 07 22:04:51 musicbox volumio[1000]: info: [1746648291807] Starting Upmpd Daemon May 07 22:04:51 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "my_music"... May 07 22:04:51 musicbox volumio[1000]: info: Loading plugin "mpd"... May 07 22:04:52 musicbox kernel: Key type cifs.spnego registered May 07 22:04:52 musicbox kernel: Key type cifs.idmap registered May 07 22:04:52 musicbox 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 07 22:04:52 musicbox kernel: CIFS: Attempting to mount //se-se01/internal/music May 07 22:04:52 musicbox kernel: cryptd: max_cpu_qlen set to 1000 May 07 22:04:52 musicbox sudo[1088]: pam_unix(sudo:session): session closed for user root May 07 22:04:52 musicbox kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE May 07 22:04:52 musicbox kernel: CIFS: VFS: \\se-se01 Send error in SessSetup = -13 May 07 22:04:52 musicbox kernel: CIFS: VFS: cifs_mount failed w/return code = -13 May 07 22:04:53 musicbox volumio[1000]: info: Loading plugin "upnp_browser"... May 07 22:04:53 musicbox volumio[1000]: info: Loading plugin "alarm-clock"... May 07 22:04:54 musicbox volumio[1000]: info: Loading plugin "airplay_emulation"... May 07 22:04:54 musicbox volumio[1000]: info: Starting Shairport Sync May 07 22:04:54 musicbox volumio[1000]: info: Loading plugin "last_100"... May 07 22:04:54 musicbox volumio[1000]: info: Loading plugin "webradio"... May 07 22:04:54 musicbox sudo[1072]: pam_unix(sudo:session): session closed for user root May 07 22:04:54 musicbox volumio[1000]: info: Loading plugin "i2s_dacs"... May 07 22:04:54 musicbox volumio[1000]: info: Loading plugin "volumiodiscovery"... May 07 22:04:54 musicbox volumio[1000]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 07 22:04:54 musicbox volumio[1000]: *** WARNING *** Please fix your application to use the native API of Avahi! May 07 22:04:54 musicbox volumio[1000]: *** WARNING *** For more information see May 07 22:04:54 musicbox node[1000]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 07 22:04:54 musicbox volumio[1000]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 07 22:04:54 musicbox volumio[1000]: *** WARNING *** Please fix your application to use the native API of Avahi! May 07 22:04:54 musicbox volumio[1000]: *** WARNING *** For more information see May 07 22:04:54 musicbox node[1000]: *** WARNING *** Please fix your application to use the native API of Avahi! May 07 22:04:54 musicbox node[1000]: *** WARNING *** For more information see May 07 22:04:54 musicbox node[1000]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 07 22:04:54 musicbox node[1000]: *** WARNING *** Please fix your application to use the native API of Avahi! May 07 22:04:54 musicbox node[1000]: *** WARNING *** For more information see May 07 22:04:54 musicbox volumio[1000]: info: Applying required configuration parameters for plugin volumiodiscovery May 07 22:04:54 musicbox volumio[1000]: info: Discovery: Started advertising with name: MusicBox May 07 22:04:54 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 07 22:04:54 musicbox volumio[1000]: info: Loading plugin "spop"... May 07 22:04:57 musicbox volumio[1000]: info: Loading plugin "ytcr"... May 07 22:05:06 musicbox volumio-remote-updater[590]: [2025-05-07 22:05:06] [connect] Successful connection May 07 22:05:07 musicbox volumio[1000]: info: Loading plugin "autostart"... May 07 22:05:07 musicbox volumio[1000]: info: Applying required configuration parameters for plugin autostart May 07 22:05:07 musicbox volumio[1000]: info: AutoStart - onVolumioStart - read config.json May 07 22:05:07 musicbox volumio[1000]: info: Loading plugin "outputs"... May 07 22:05:07 musicbox volumio[1000]: info: Loading plugin "albumart"... May 07 22:05:07 musicbox volumio[1000]: info: Plugin example_plugin is not enabled May 07 22:05:07 musicbox volumio[1000]: info: Loading plugin "inputs"... May 07 22:05:07 musicbox volumio[1000]: info: Loading plugin "updater_comm"... May 07 22:05:08 musicbox volumio[1000]: info: Plugin mpdemulation is not enabled May 07 22:05:08 musicbox volumio[1000]: info: Loading plugin "rest_api"... May 07 22:05:08 musicbox volumio[1000]: info: Loading plugin "websocket"... May 07 22:05:08 musicbox volumio[1000]: info: Starting Socket.io Server version 2.3.0 May 07 22:05:08 musicbox volumio[1000]: info: Loading plugin "backup_restore"... May 07 22:05:08 musicbox volumio[1000]: Forking 3 albumart workers May 07 22:05:08 musicbox volumio[1000]: info: Applying required configuration parameters for plugin backup_restore May 07 22:05:08 musicbox volumio[1000]: info: Loading plugin "rotaryencoder2"... May 07 22:05:09 musicbox volumio[1000]: info: Loading i18n strings for locale de May 07 22:05:09 musicbox volumio[1000]: Updating browse sources language May 07 22:05:09 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 07 22:05:10 musicbox volumio[1000]: Starting albumart workers May 07 22:05:10 musicbox volumio[1000]: Starting albumart workers May 07 22:05:10 musicbox volumio[1000]: Starting albumart workers May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::initPlayerControls May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 07 22:05:10 musicbox volumio[1000]: Express server listening on port 3000 May 07 22:05:10 musicbox volumio[1000]: [Metrics] WebUI: 26s 402.79ms May 07 22:05:10 musicbox volumio[1000]: info: CoreStateMachine::resetVolumioState May 07 22:05:10 musicbox volumio[1000]: info: CoreStateMachine::getcurrentVolume May 07 22:05:10 musicbox volumio[1000]: info: CoreCommandRouter::volumioRetrievevolume May 07 22:05:10 musicbox sudo[1180]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 07 22:05:10 musicbox sudo[1178]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 07 22:05:10 musicbox sudo[1180]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:10 musicbox sudo[1178]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:10 musicbox sudo[1180]: pam_unix(sudo:session): session closed for user root May 07 22:05:10 musicbox sudo[1178]: pam_unix(sudo:session): session closed for user root May 07 22:05:10 musicbox volumio[1000]: info: Volumio Network Manager: Network status updated: 2 May 07 22:05:10 musicbox volumio[1000]: info: Cannot mount NAS Musik at system boot, trial number 1 ,retrying in 5 seconds May 07 22:05:11 musicbox volumio-remote-updater[590]: [2025-05-07 22:05:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1746648306 101 May 07 22:05:11 musicbox volumio[1000]: 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 07 22:05:11 musicbox volumio[1000]: info: VolumeController:: Volume=32 Mute =false May 07 22:05:11 musicbox volumio[1000]: info: CoreStateMachine::pushState May 07 22:05:11 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:11 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 07 22:05:11 musicbox volumio[1000]: info: CoreCommandRouter::volumioPushState May 07 22:05:11 musicbox volumio[1000]: info: CoreStateMachine::updateTrackBlock May 07 22:05:11 musicbox volumio[1000]: info: CorePlayQueue::getTrackBlock May 07 22:05:11 musicbox volumio[1000]: info: CoreCommandRouter::volumioRetrievevolume May 07 22:05:11 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 07 22:05:11 musicbox volumio[1000]: info: Executing start script for DAC IQaudIO DAC Plus May 07 22:05:11 musicbox volumio[1000]: info: Reloading queue from file May 07 22:05:11 musicbox volumio[1000]: info: CoreStateMachine::setRepeat true single undefined May 07 22:05:11 musicbox volumio[1000]: info: CoreStateMachine::pushState May 07 22:05:11 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:11 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 07 22:05:11 musicbox volumio[1000]: info: CoreCommandRouter::volumioPushState May 07 22:05:11 musicbox volumio[1000]: info: CoreStateMachine::setRandom true May 07 22:05:11 musicbox volumio[1000]: info: CoreStateMachine::pushState May 07 22:05:11 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:11 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 07 22:05:11 musicbox volumio[1000]: info: CoreCommandRouter::volumioPushState May 07 22:05:11 musicbox volumio[1000]: info: Setting Device type: Raspberry PI May 07 22:05:11 musicbox volumio[1000]: info: DAC script executed May 07 22:05:11 musicbox volumio[1000]: info: Completed loading Core Plugins May 07 22:05:11 musicbox volumio[1000]: info: Preparing to generate the ALSA configuration file May 07 22:05:12 musicbox volumio[1000]: info: VolumeController:: Volume=32 Mute =false May 07 22:05:12 musicbox volumio[1000]: info: CoreStateMachine::pushState May 07 22:05:12 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::volumioPushState May 07 22:05:12 musicbox sudo[1234]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 07 22:05:12 musicbox sudo[1234]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:12 musicbox volumio[1000]: info: Discovery: adding 95307504-9fd1-4df0-a09a-bb5004682349 May 07 22:05:12 musicbox volumio[1000]: info: Discovery: Found device MusicBox May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::volumioGetState May 07 22:05:12 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:12 musicbox volumio[1000]: info: Asound.conf file unchanged, so no further update is needed May 07 22:05:12 musicbox volumio[1000]: info: Output device has changed, restarting MPD May 07 22:05:12 musicbox systemd[1]: Started UPnP Renderer front-end to MPD. May 07 22:05:12 musicbox sudo[1234]: pam_unix(sudo:session): session closed for user root May 07 22:05:12 musicbox volumio[1000]: info: Output device has changed, restarting Shairport Sync May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 07 22:05:12 musicbox sudo[1238]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 07 22:05:12 musicbox sudo[1238]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:12 musicbox sudo[1240]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 07 22:05:12 musicbox sudo[1240]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:12 musicbox sudo[1238]: pam_unix(sudo:session): session closed for user root May 07 22:05:12 musicbox systemd[1]: Stopping Music Player Daemon... May 07 22:05:12 musicbox volumio[1000]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 07 22:05:12 musicbox volumio[1000]: info: ___________ START PLUGINS ___________ May 07 22:05:12 musicbox volumio[1000]: info: ControllerMpd::onStart: Initializing MPD May 07 22:05:12 musicbox volumio[1000]: info: Creating MPD Configuration file May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 07 22:05:12 musicbox volumio[1000]: info: [1746648312496] CoreMusicLibrary::Adding element Medienserver May 07 22:05:12 musicbox sudo[1247]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 07 22:05:12 musicbox sudo[1247]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:12 musicbox sudo[1247]: pam_unix(sudo:session): session closed for user root May 07 22:05:12 musicbox sudo[1249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 07 22:05:12 musicbox sudo[1249]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 07 22:05:12 musicbox systemd[1]: mpd.service: Succeeded. May 07 22:05:12 musicbox systemd[1]: Stopped Music Player Daemon. May 07 22:05:12 musicbox systemd[1]: Starting Music Player Daemon... May 07 22:05:12 musicbox volumio[1000]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 07 22:05:12 musicbox volumio[1000]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 07 22:05:12 musicbox volumio[1000]: info: [1746648312778] CoreMusicLibrary::Adding element Last_100 May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 07 22:05:12 musicbox volumio[1000]: info: [1746648312784] CoreMusicLibrary::Adding element Webradio May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 07 22:05:12 musicbox volumio[1000]: info: Initializing BBC Radios May 07 22:05:12 musicbox sudo[1255]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 07 22:05:12 musicbox sudo[1255]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:12 musicbox sudo[1255]: pam_unix(sudo:session): session closed for user root May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 07 22:05:12 musicbox volumio[1000]: info: Creating Spotify config file May 07 22:05:12 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:13 musicbox volumio[1000]: info: AutoStart - onStart May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] loadI18nStrings: /data/plugins/system_hardware/rotaryencoder2/i18n/strings_de.json May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] loadI18nStrings: loaded: May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] onStart: Config loaded: May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] installAllOverlays: 1,2,3 May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] installAllOverlays: 1,2 May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] installAllOverlays: 1 May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] installAllOverlays: May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] installAllOverlays: end of recursion. May 07 22:05:13 musicbox volumio[1000]: info: Volumio Calling Home May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] addOverlay for Rotary: 23 27 1 May 07 22:05:13 musicbox volumio[1000]: info: [ROTARYENCODER2] addOverlay: executing command: /usr/bin/sudo /usr/bin/dtoverlay rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 & May 07 22:05:13 musicbox sudo[1275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 May 07 22:05:13 musicbox sudo[1275]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:13 musicbox kernel: rotary-encoder rotary@17: gray May 07 22:05:13 musicbox kernel: input: rotary@17 as /devices/platform/rotary@17/input/input0 May 07 22:05:13 musicbox sudo[1275]: pam_unix(sudo:session): session closed for user root May 07 22:05:13 musicbox volumio[1000]: info: MPD Permissions set May 07 22:05:13 musicbox volumio[1000]: info: MPD Permissions set May 07 22:05:13 musicbox volumio[1000]: info: Upmpdcli Daemon Started May 07 22:05:13 musicbox volumio[1000]: info: Volumio called home May 07 22:05:13 musicbox volumio[1000]: info: Spotify config file written May 07 22:05:13 musicbox sudo[1291]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 07 22:05:13 musicbox sudo[1291]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:14 musicbox systemd-udevd[1282]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. May 07 22:05:14 musicbox systemd[1]: Started go-librespot Daemon. May 07 22:05:14 musicbox go-librespot[1294]: go-librespot daemon starting... May 07 22:05:14 musicbox sudo[1291]: pam_unix(sudo:session): session closed for user root May 07 22:05:14 musicbox volumio[1000]: 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 07 22:05:14 musicbox volumio[1000]: 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 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 07 22:05:14 musicbox volumio[1000]: info: No need to fix Spotify hosts May 07 22:05:14 musicbox go-librespot[1294]: time="2025-05-07T22:05:14+02:00" level=info msg="running go-librespot 0.2.0" May 07 22:05:14 musicbox go-librespot[1294]: time="2025-05-07T22:05:14+02:00" level=debug msg="app state loaded" May 07 22:05:14 musicbox go-librespot[1294]: time="2025-05-07T22:05:14+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 07 22:05:14 musicbox volumio[1000]: info: /dev/input: May 07 22:05:14 musicbox volumio[1000]: event0 May 07 22:05:14 musicbox volumio[1000]: mice May 07 22:05:14 musicbox volumio[1000]: info: [ROTARYENCODER2] addOverlay for Button: 4 true up May 07 22:05:14 musicbox volumio[1000]: info: [ROTARYENCODER2] addOverlay: executing command: /usr/bin/sudo /usr/bin/dtoverlay gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 & May 07 22:05:14 musicbox volumio[1000]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 07 22:05:14 musicbox volumio[1000]: SPOTIFY: BQAWzndgxC9otYDFQkzKjUo8ROJ_a-ItE_RaRHprPedxy7qQ7_OGGTMYC12zapi46KqHnS089f90Lvn_ROxoh7YvoDl8ZN3YZtCLviWqFE1B0Y-8sNwmViOE0dWo3EXGcPLRNTlK26h2FGgMJMDf6tTl4rFTHd0OYVVuzm6He5mkrODKI2QIoqDQB6f2U8yS-zih0-aEBhofN6-O7j1uhiTsxinTZNmvqwgnBImqlf4cq_a0CaJN8dZqI_x6PJnWilMWzVJDA8v5NJtIfMDFGe83od46f-Tz-clf6jF9SVGIM7jFJps May 07 22:05:14 musicbox volumio[1000]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 07 22:05:14 musicbox volumio[1000]: info: New Spotify access token = BQAWzndgxC9otYDFQkzKjUo8ROJ_a-ItE_RaRHprPedxy7qQ7_OGGTMYC12zapi46KqHnS089f90Lvn_ROxoh7YvoDl8ZN3YZtCLviWqFE1B0Y-8sNwmViOE0dWo3EXGcPLRNTlK26h2FGgMJMDf6tTl4rFTHd0OYVVuzm6He5mkrODKI2QIoqDQB6f2U8yS-zih0-aEBhofN6-O7j1uhiTsxinTZNmvqwgnBImqlf4cq_a0CaJN8dZqI_x6PJnWilMWzVJDA8v5NJtIfMDFGe83od46f-Tz-clf6jF9SVGIM7jFJps May 07 22:05:14 musicbox volumio[1000]: info: Spotify credentials grant success - running version from March 24, 2019 May 07 22:05:14 musicbox sudo[1310]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 May 07 22:05:14 musicbox sudo[1310]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:15 musicbox systemd[1]: systemd-timedated.service: Succeeded. May 07 22:05:15 musicbox sudo[1310]: pam_unix(sudo:session): session closed for user root May 07 22:05:15 musicbox kernel: input: button@4 as /devices/platform/button@4/input/input1 May 07 22:05:15 musicbox volumio[1000]: info: Starting Shairport Sync May 07 22:05:15 musicbox volumio[1000]: info: Starting Shairport Sync May 07 22:05:15 musicbox volumio[1000]: info: Starting Shairport Sync May 07 22:05:15 musicbox sudo[1324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 07 22:05:15 musicbox sudo[1324]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:15 musicbox sudo[1326]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 07 22:05:15 musicbox sudo[1326]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:15 musicbox sudo[1331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 07 22:05:15 musicbox sudo[1331]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:15 musicbox volumio[1000]: info: CoreCommandRouter::volumioGetState May 07 22:05:15 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:15 musicbox volumio[1000]: info: CoreCommandRouter::volumioGetState May 07 22:05:15 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:15 musicbox systemd-udevd[1321]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. May 07 22:05:15 musicbox systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 07 22:05:15 musicbox systemd[1]: shairport-sync.service: Succeeded. May 07 22:05:15 musicbox systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 07 22:05:15 musicbox systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 07 22:05:15 musicbox sudo[1331]: pam_unix(sudo:session): session closed for user root May 07 22:05:15 musicbox sudo[1326]: pam_unix(sudo:session): session closed for user root May 07 22:05:15 musicbox sudo[1324]: pam_unix(sudo:session): session closed for user root May 07 22:05:15 musicbox go-librespot[1294]: time="2025-05-07T22:05:15+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 07 22:05:15 musicbox go-librespot[1294]: time="2025-05-07T22:05:15+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 07 22:05:15 musicbox go-librespot[1294]: time="2025-05-07T22:05:15+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 07 22:05:15 musicbox go-librespot[1294]: time="2025-05-07T22:05:15+02:00" level=info msg="zeroconf server listening on port 39375" May 07 22:05:15 musicbox volumio[1000]: info: Shairport-Sync Started May 07 22:05:15 musicbox volumio[1000]: Error adding Membership: Error: addMembership EINVAL May 07 22:05:15 musicbox volumio[1000]: info: Shairport-Sync Started May 07 22:05:15 musicbox volumio[1000]: info: Shairport-Sync Started May 07 22:05:15 musicbox volumio[1000]: info: /dev/input: May 07 22:05:15 musicbox volumio[1000]: by-path May 07 22:05:15 musicbox volumio[1000]: event0 May 07 22:05:15 musicbox volumio[1000]: event1 May 07 22:05:15 musicbox volumio[1000]: mice May 07 22:05:15 musicbox volumio[1000]: /dev/input/by-path: May 07 22:05:15 musicbox volumio[1000]: platform-button@4-event May 07 22:05:15 musicbox volumio[1000]: platform-rotary@17-event May 07 22:05:15 musicbox go-librespot[1294]: time="2025-05-07T22:05:15+02:00" level=debug msg="obtained new client token: AACa4bTmqzttZp/pQp3O6hsVCbNcjcM86T4VAOrq83QHvo30jHpLlAxYMwyhkk7P+11Uyu8pK3yxew7Kch0NfZdebwJz+64+kXHcnHJDp5J5XRKiDiXfLzNnscMsptV/oa+RQFeFtxm26VXQqaYjYMmeUZnruwj8R0qD7SmR867HeWX3XnY1UGljYJa7l6M9RoNJIerwrr9LEQbu22wXqZlDdR8M3HXm1HGpj6XNMtaamJIuC8TjqcaL" May 07 22:05:15 musicbox volumio[1000]: SPOTIFY: User informations: {"country":"EG","display_name":"Lukas Trausch","email":"admin@trauschnet.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31bjkbz74djgmahibcw3dkhb6sha"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31bjkbz74djgmahibcw3dkhb6sha","id":"31bjkbz74djgmahibcw3dkhb6sha","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85346c5c7f5100ec893b77cef9","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82346c5c7f5100ec893b77cef9","width":64}],"product":"premium","type":"user","uri":"spotify:user:31bjkbz74djgmahibcw3dkhb6sha"} May 07 22:05:15 musicbox volumio[1000]: info: Spotify Successfully logged in May 07 22:05:15 musicbox volumio[1000]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 07 22:05:15 musicbox volumio[1000]: info: [1746648315932] CoreMusicLibrary::Adding element Spotify May 07 22:05:15 musicbox volumio[1000]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 07 22:05:15 musicbox volumio[1000]: Cannot find translation for source Spotify May 07 22:05:15 musicbox go-librespot[1294]: time="2025-05-07T22:05:15+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="completed keyexchange" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="completed challenge" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=info msg="authenticated AP as 31bjkbz74djgmahibcw3dkhb6sha" May 07 22:05:16 musicbox sudo[1340]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=lukas,password=Pia0815@2612,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //se-se01/internal/music /mnt/NAS/Musik May 07 22:05:16 musicbox sudo[1340]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:16 musicbox kernel: CIFS: Attempting to mount //se-se01/internal/music May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=info msg="authenticated Login5 as 31bjkbz74djgmahibcw3dkhb6sha" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="initializing zeroconf session, username: 31bjkbz74djgmahibcw3dkhb6sha" May 07 22:05:16 musicbox mpd[1270]: May 07 22:05 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 07 22:05:16 musicbox systemd[1]: Started Music Player Daemon. May 07 22:05:16 musicbox volumio[1000]: Upnp client error: Error: This socket has been ended by the other party May 07 22:05:16 musicbox sudo[1240]: pam_unix(sudo:session): session closed for user root May 07 22:05:16 musicbox sudo[1249]: pam_unix(sudo:session): session closed for user root May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="dealer connection opened" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=trace msg="starting accesspoint recv loop" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=trace msg="starting dealer recv loop" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=trace msg="received accesspoint ping" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="received connection id: YWQ4ZjQ0ZjgtZTgxYS00YmMwLTlhY2MtMjc3ZGViY2YwMmUzK2RlYWxlcit0Y3A6Ly8wYWNhNTgwNC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQzE1QTFCNjVCQzEzNkZCOTBEMkRDRENEOUNEOUQ4QzJFNEQ2MEQxNDU0QzMxRjU0M0FGN0MzQUE0QjJFQjU4OA==" May 07 22:05:16 musicbox volumio[1000]: error: MPD error: The expression evaluated to a falsy value: May 07 22:05:16 musicbox volumio[1000]: assert.ok(self.idling) May 07 22:05:16 musicbox volumio[1000]: error: The expression evaluated to a falsy value: May 07 22:05:16 musicbox volumio[1000]: assert.ok(self.idling) May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="put connect state because NEW_DEVICE" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 07 22:05:16 musicbox go-librespot[1294]: time="2025-05-07T22:05:16+02:00" level=trace msg="received accesspoint pong ack" May 07 22:05:16 musicbox volumio[1000]: info: MPD running with PID1270 May 07 22:05:16 musicbox volumio[1000]: ,establishing connection May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners: 1,2,3 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners: 1,2 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners: 1 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners: May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners: end of recursion. May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] checkOverlayExists: Checking for existing overlays for Rotary: 1 type: rotary May 07 22:05:16 musicbox volumio[1000]: error: updateQueue error: null May 07 22:05:16 musicbox volumio[1000]: error: updateQueue error: null May 07 22:05:16 musicbox sudo[1351]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l May 07 22:05:16 musicbox sudo[1351]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:16 musicbox sudo[1351]: pam_unix(sudo:session): session closed for user root May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] checkOverlayExists: check pinA=23pinB=27 in Overlays (in load order): May 07 22:05:16 musicbox volumio[1000]: 0: rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 May 07 22:05:16 musicbox volumio[1000]: 1: gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] checkOverlayExists: rotary 1 uses overlay 0 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners: attach rotary 1 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachListener: path: /dev/input/by-path/platform-rotary@17-event, type: rotary May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] checkOverlayExists: Checking for existing overlays for Rotary: 1 type: button May 07 22:05:16 musicbox sudo[1368]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l May 07 22:05:16 musicbox sudo[1368]: pam_unix(sudo:session): session opened for user root by (uid=0) May 07 22:05:16 musicbox sudo[1368]: pam_unix(sudo:session): session closed for user root May 07 22:05:16 musicbox volumio[1236]: Generating RSA private key, 4096 bit long modulus (2 primes) May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] checkOverlayExists: check pinA=4pinB=undefined in Overlays (in load order): May 07 22:05:16 musicbox volumio[1000]: 0: rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 May 07 22:05:16 musicbox volumio[1000]: 1: gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] checkOverlayExists: button 1 uses overlay 1 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners: attach button 1 May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachListener: path: /dev/input/by-path/platform-button@4-event, type: button May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners rotaries: May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners buttons: May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners rotaries: May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] attachAllListeners buttons: May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] onStart: Attach Event-handles now. May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] Now addAllEventHandles for rotaries. May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] addEventHandle for rotary: 1 type: rotary May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] Now addAllEventHandles for buttons. May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] addEventHandle for rotary: 1 type: button May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] addEventHandle: adding handle : May 07 22:05:16 musicbox volumio[1000]: info: [ROTARYENCODER2] onStart: Plugin successfully started. May 07 22:05:17 musicbox volumio[1000]: info: [yt-cast-receiver] DIAL server listening on port 8098 May 07 22:05:17 musicbox volumio[1000]: info: CoreCommandRouter::volumioRetrievevolume May 07 22:05:17 musicbox volumio[1000]: info: VolumeController:: Volume=32 Mute =false May 07 22:05:17 musicbox volumio[1000]: info: CoreCommandRouter::volumioGetState May 07 22:05:17 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:17 musicbox volumio[1000]: info: CoreStateMachine::pushState May 07 22:05:17 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:17 musicbox volumio[1000]: info: CoreCommandRouter::volumioPushState May 07 22:05:17 musicbox volumio[1000]: info: Completed starting Core Plugins May 07 22:05:17 musicbox volumio[1000]: info: ------------------------------------------- May 07 22:05:17 musicbox volumio[1000]: info: ----- MyVolumio plugins startup ---- May 07 22:05:17 musicbox volumio[1000]: info: ------------------------------------------- May 07 22:05:17 musicbox volumio[1000]: info: [MyVolumio PluginManager] Fetching plans data.... May 07 22:05:17 musicbox volumio[1000]: info: go-librespot daemon successfully initialized May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=debug msg="handling transfer player command from 4f6d92d4de3070df3f2f043297ebb8c579d5c8c8" May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DX9wC1KY45plY" May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=trace msg="fetched new page 0 with 100 items (list: 100)" uri="spotify:playlist:37i9dQZF1DX9wC1KY45plY" May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=debug msg="shuffled context with seed 11971048956425560136 (len: 100, keep: 32)" uri="spotify:playlist:37i9dQZF1DX9wC1KY45plY" May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=debug msg="loading track (paused: false, position: 197290ms)" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=trace msg="emitting websocket event: will_play" May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=debug msg="selected format OGG_VORBIS_160 (c2aa4aeaa2e1c40be3faf8d2739d99ce241a32c9)" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:18 musicbox go-librespot[1294]: time="2025-05-07T22:05:18+02:00" level=debug msg="requested aes key for file c2aa4aeaa2e1c40be3faf8d2739d99ce241a32c9, gid: 7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:19 musicbox go-librespot[1294]: time="2025-05-07T22:05:19+02:00" level=debug msg="fetched first chunk of 15, total size is 7370580 bytes" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:19 musicbox go-librespot[1294]: time="2025-05-07T22:05:19+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:19 musicbox go-librespot[1294]: time="2025-05-07T22:05:19+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:19 musicbox go-librespot[1294]: time="2025-05-07T22:05:19+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:19 musicbox go-librespot[1294]: time="2025-05-07T22:05:19+02:00" level=debug msg="fetched chunk 8/14, size: 524288" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:19 musicbox go-librespot[1294]: time="2025-05-07T22:05:19+02:00" level=debug msg="fetched chunk 10/14, size: 524288" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:20 musicbox volumio[1000]: info: Initializing connection to go-librespot Websocket May 07 22:05:20 musicbox go-librespot[1294]: time="2025-05-07T22:05:20+02:00" level=debug msg="new websocket client" May 07 22:05:20 musicbox volumio[1000]: info: Connection to go-librespot Websocket established May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=debug msg="fetched chunk 7/14, size: 524288" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=debug msg="fetched chunk 9/14, size: 524288" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=trace msg="seek to 197290ms (diff: 197158ms, samples: 8700489, bytes: 3816917)" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=debug msg="created new output device" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=info msg="loaded track \"Heroes - 2017 Remaster\" (paused: false, position: 197290ms, duration: 371413ms, prefetched: false)" uri="spotify:track:7Jh1bpe76CNTCgdgAdBw4Z" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=trace msg="scheduling prefetch in 144s" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=trace msg="emitting websocket event: metadata" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=trace msg="emitting websocket event: active" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=debug msg="sending successful reply for dealer request" May 07 22:05:21 musicbox volumio[1000]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7Jh1bpe76CNTCgdgAdBw4Z","name":"Heroes - 2017 Remaster","artist_names":["David Bowie"],"album_name":"\"Heroes\" (2017 Remaster)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02204f41d52743c6a9efd62985","position":197290,"duration":371413,"release_date":"year:1977","track_number":3,"disc_number":1}} May 07 22:05:21 musicbox volumio[1000]: SPOTIFY: received: {"type":"active","data":null} May 07 22:05:21 musicbox volumio[1000]: info: Aligning Spotify Volume to Volumio Volume May 07 22:05:21 musicbox volumio[1000]: info: CoreCommandRouter::volumioGetState May 07 22:05:21 musicbox volumio[1000]: info: CorePlayQueue::getTrack 0 May 07 22:05:21 musicbox volumio[1000]: info: Setting Spotify Volume from Volumio: 32 May 07 22:05:21 musicbox volumio[1000]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 07 22:05:21 musicbox go-librespot[1294]: time="2025-05-07T22:05:21+02:00" level=trace msg="emitting websocket event: playing" May 07 22:05:21 musicbox volumio[1000]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7Jh1bpe76CNTCgdgAdBw4Z","play_origin":"playlist"}} May 07 22:05:21 musicbox volumio[1000]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 07 22:05:21 musicbox volumio[1000]: TypeError: Cannot read property 'service' of undefined May 07 22:05:21 musicbox volumio[1000]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) May 07 22:05:21 musicbox volumio[1000]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) May 07 22:05:21 musicbox volumio[1000]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) May 07 22:05:21 musicbox volumio[1000]: at WebSocket.emit (events.js:315:20) May 07 22:05:21 musicbox volumio[1000]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 07 22:05:21 musicbox volumio[1000]: at Receiver.emit (events.js:315:20) May 07 22:05:21 musicbox volumio[1000]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 07 22:05:21 musicbox volumio[1000]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 07 22:05:21 musicbox volumio[1000]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 07 22:05:21 musicbox volumio[1000]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 07 22:05:21 musicbox volumio[1000]: at writeOrBuffer (internal/streams/writable.js:358:12) May 07 22:05:21 musicbox volumio[1000]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 07 22:05:21 musicbox volumio[1000]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 07 22:05:21 musicbox volumio[1000]: at Socket.emit (events.js:315:20) May 07 22:05:21 musicbox volumio[1000]: at addChunk (internal/streams/readable.js:309:12) May 07 22:05:21 musicbox volumio[1000]: at readableAddChunk (internal/streams/readable.js:284:9) May 07 22:05:21 musicbox volumio[1000]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 07 22:05:21 musicbox volumio[1236]: .................++++ May 07 22:05:22 musicbox sudo[1436]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-07 22:04 May 07 22:05:22 musicbox sudo[1436]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="a01a833dd28483f88cb390596f5090b7187992af" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 27 Feb 2025 11:42:54 AM CET" VOLUMIO_VERSION="3.795" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4049a67f1c09d4a94e033ba35a80a144"