-- Logs begin at Wed 2025-12-17 23:16:49 CET, end at Wed 2025-12-17 23:18:21 CET. -- Dec 17 23:17:00 musicbox ntpd[753]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Dec 17 23:17:00 musicbox sudo[812]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:00 musicbox wireless.js[579]: Stopped aP Dec 17 23:17:00 musicbox sudo[819]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Dec 17 23:17:00 musicbox sudo[819]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:00 musicbox sudo[819]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:00 musicbox kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Dec 17 23:17:00 musicbox sudo[821]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Dec 17 23:17:00 musicbox sudo[821]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:00 musicbox sudo[821]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:00 musicbox sudo[828]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Dec 17 23:17:00 musicbox sudo[828]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:00 musicbox sudo[828]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:00 musicbox sudo[830]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Dec 17 23:17:00 musicbox sudo[830]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:01 musicbox ntpd[753]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Dec 17 23:17:01 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:01] [info] asio async_connect error: system:111 (Connection refused) Dec 17 23:17:01 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:01] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Dec 17 23:17:01 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:01] [error] handle_connect error: Underlying Transport Error Dec 17 23:17:01 musicbox bthelper[656]: Changing power off succeeded Dec 17 23:17:01 musicbox volumio-time-update[580]: volumio-time-update-util: Fetching time from Volumio... Dec 17 23:17:01 musicbox volumio-time-update[580]: volumio-time-update-util: Date not found in response Dec 17 23:17:01 musicbox volumio-time-update[580]: volumio-time-update-util: Retrying in 5 seconds... Dec 17 23:17:01 musicbox bthelper[656]: [CHG] Controller B8:27:EB:91:D7:0E Class: 0x0000041c Dec 17 23:17:01 musicbox bthelper[656]: Changing power on succeeded Dec 17 23:17:03 musicbox sudo[830]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:03 musicbox wireless.js[579]: Start wireless flow Dec 17 23:17:03 musicbox wireless.js[579]: Stopped hotspot (if there).. Dec 17 23:17:03 musicbox sudo[845]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Dec 17 23:17:03 musicbox sudo[845]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:03 musicbox sudo[845]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:03 musicbox sudo[847]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Dec 17 23:17:03 musicbox sudo[847]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:03 musicbox sudo[847]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:03 musicbox wireless.js[579]: DHCP IP Dec 17 23:17:03 musicbox wireless.js[579]: Start ap Dec 17 23:17:03 musicbox wpa_supplicant[849]: Successfully initialized wpa_supplicant Dec 17 23:17:03 musicbox sudo[850]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Dec 17 23:17:03 musicbox sudo[850]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:04 musicbox kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Dec 17 23:17:04 musicbox dhcpcd[851]: dev: loaded udev Dec 17 23:17:04 musicbox dhcpcd-run-hooks[869]: wlan0: starting wpa_supplicant Dec 17 23:17:04 musicbox dhcpcd-run-hooks[874]: wlan0: failed to start wpa_supplicant Dec 17 23:17:04 musicbox dhcpcd-run-hooks[875]: wlan0: Successfully initialized wpa_supplicant nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Ma Dec 17 23:17:04 musicbox dhcpcd[851]: wlan0: connected to Access Point `' Dec 17 23:17:04 musicbox dhcpcd[851]: no interfaces have a carrier Dec 17 23:17:04 musicbox dhcpcd[851]: forked to background, child pid 885 Dec 17 23:17:04 musicbox dhcpcd[885]: eth0: waiting for carrier Dec 17 23:17:04 musicbox dhcpcd[885]: wlan0: waiting for carrier Dec 17 23:17:04 musicbox sudo[850]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:04 musicbox wireless.js[579]: trying... Dec 17 23:17:05 musicbox sudo[887]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:05 musicbox sudo[887]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:05 musicbox sudo[887]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:05 musicbox wireless.js[579]: trying... Dec 17 23:17:06 musicbox sudo[890]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:06 musicbox sudo[890]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:06 musicbox sudo[890]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:06 musicbox volumio-time-update[580]: volumio-time-update-util: Fetching time from Volumio... Dec 17 23:17:06 musicbox volumio-time-update[580]: volumio-time-update-util: Date not found in response Dec 17 23:17:06 musicbox volumio-time-update[580]: volumio-time-update-util: Retrying in 5 seconds... Dec 17 23:17:06 musicbox wireless.js[579]: trying... Dec 17 23:17:07 musicbox sudo[898]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:07 musicbox sudo[898]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:07 musicbox sudo[898]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:07 musicbox wireless.js[579]: trying... Dec 17 23:17:08 musicbox sudo[901]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:08 musicbox sudo[901]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:08 musicbox sudo[901]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:08 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:08] [info] asio async_connect error: system:111 (Connection refused) Dec 17 23:17:08 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:08] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Dec 17 23:17:08 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:08] [error] handle_connect error: Underlying Transport Error Dec 17 23:17:08 musicbox wireless.js[579]: trying... Dec 17 23:17:09 musicbox sudo[904]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:09 musicbox sudo[904]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:09 musicbox sudo[904]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:09 musicbox wireless.js[579]: trying... Dec 17 23:17:10 musicbox sudo[907]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:10 musicbox sudo[907]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:10 musicbox sudo[907]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:10 musicbox wpa_supplicant[873]: wlan0: Trying to associate with SSID 'TrauschNet Privat' Dec 17 23:17:10 musicbox dhcpcd[885]: wlan0: carrier acquired Dec 17 23:17:10 musicbox wpa_supplicant[873]: wlan0: Associated with 0c:72:74:e6:49:57 Dec 17 23:17:10 musicbox wpa_supplicant[873]: wlan0: CTRL-EVENT-CONNECTED - Connection to 0c:72:74:e6:49:57 completed [id=0 id_str=] Dec 17 23:17:10 musicbox dhcpcd[885]: wlan0: connected to Access Point `TrauschNet Privat' Dec 17 23:17:10 musicbox wpa_supplicant[873]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Dec 17 23:17:10 musicbox wpa_supplicant[873]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Dec 17 23:17:10 musicbox dhcpcd[885]: DUID 00:01:00:01:2c:c5:41:c9:b8:27:eb:6e:28:f1 Dec 17 23:17:10 musicbox dhcpcd[885]: wlan0: IAID eb:6e:28:f1 Dec 17 23:17:10 musicbox dhcpcd[885]: wlan0: adding address fe80::316a:333e:60f6:d02b Dec 17 23:17:10 musicbox dhcpcd[885]: ipv6_addaddr1: Permission denied Dec 17 23:17:10 musicbox dhcpcd[885]: wlan0: carrier lost Dec 17 23:17:10 musicbox dhcpcd[885]: wlan0: carrier acquired Dec 17 23:17:10 musicbox dhcpcd[885]: wlan0: IAID eb:6e:28:f1 Dec 17 23:17:10 musicbox wireless.js[579]: trying... Dec 17 23:17:11 musicbox sudo[923]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:11 musicbox sudo[923]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:11 musicbox sudo[923]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:11 musicbox dhcpcd[885]: wlan0: rebinding lease of 192.168.178.119 Dec 17 23:17:11 musicbox dhcpcd[885]: wlan0: probing address 192.168.178.119/24 Dec 17 23:17:11 musicbox volumio-time-update[580]: volumio-time-update-util: Fetching time from Volumio... Dec 17 23:17:11 musicbox dhcpcd[885]: wlan0: soliciting an IPv6 router Dec 17 23:17:11 musicbox volumio-time-update[580]: volumio-time-update-util: Date not found in response Dec 17 23:17:11 musicbox volumio-time-update[580]: volumio-time-update-util: Retrying in 5 seconds... Dec 17 23:17:11 musicbox wireless.js[579]: trying... Dec 17 23:17:12 musicbox sudo[931]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:12 musicbox sudo[931]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:12 musicbox sudo[931]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:12 musicbox wireless.js[579]: trying... Dec 17 23:17:13 musicbox sudo[934]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:13 musicbox sudo[934]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:13 musicbox sudo[934]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:13 musicbox wireless.js[579]: trying... Dec 17 23:17:14 musicbox sudo[937]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:14 musicbox sudo[937]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:14 musicbox sudo[937]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:14 musicbox wireless.js[579]: trying... Dec 17 23:17:15 musicbox sudo[940]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:15 musicbox sudo[940]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:15 musicbox sudo[940]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:15 musicbox wireless.js[579]: trying... Dec 17 23:17:16 musicbox sudo[943]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:16 musicbox sudo[943]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:16 musicbox sudo[943]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:16 musicbox dhcpcd[885]: wlan0: leased 192.168.178.119 for 604800 seconds Dec 17 23:17:16 musicbox avahi-daemon[610]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.119. Dec 17 23:17:16 musicbox dhcpcd[885]: wlan0: adding route to 192.168.178.0/24 Dec 17 23:17:16 musicbox dhcpcd[885]: wlan0: adding default route via 192.168.178.1 Dec 17 23:17:16 musicbox avahi-daemon[610]: New relevant interface wlan0.IPv4 for mDNS. Dec 17 23:17:16 musicbox avahi-daemon[610]: Registering new address record for 192.168.178.119 on wlan0.IPv4. Dec 17 23:17:16 musicbox volumio-time-update[580]: volumio-time-update-util: Fetching time from Volumio... Dec 17 23:17:16 musicbox volumio-time-update[580]: volumio-time-update-util: Setting system time to: 2025-12-17 23:17:41 Dec 17 23:17:16 musicbox sudo[971]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-12-17 23:17:41 Dec 17 23:17:16 musicbox sudo[971]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:16 musicbox wireless.js[579]: trying... Dec 17 23:17:16 musicbox dbus-daemon[583]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.9' (uid=0 pid=972 comm="timedatectl set-time 2025-12-17 23:17:41 ") Dec 17 23:17:17 musicbox sudo[974]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 17 23:17:17 musicbox sudo[974]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:17 musicbox sudo[974]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:17 musicbox wireless.js[579]: Connected to: ----TrauschNet Privat Dec 17 23:17:17 musicbox wireless.js[579]: ---- Dec 17 23:17:17 musicbox sudo[978]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 17 23:17:17 musicbox sudo[978]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:17 musicbox sudo[978]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:17 musicbox systemd[1]: Starting Time & Date Service... Dec 17 23:17:17 musicbox wireless.js[579]: ... joined AP, wlan0 IPv4 is 192.168.178.119, ipV6 is undefined Dec 17 23:17:17 musicbox wireless.js[579]: It's done! AP Dec 17 23:17:17 musicbox kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Dec 17 23:17:17 musicbox systemd[1]: Started Wireless Services. Dec 17 23:17:17 musicbox systemd[1]: Started Volumio Backend Module. Dec 17 23:17:17 musicbox systemd[1]: Started Volumio Cpu Tweaker. Dec 17 23:17:17 musicbox volumio-cpu-tweak[984]: Setting RT Priority for mpd Dec 17 23:17:17 musicbox volumio-cpu-tweak[984]: pid 35's current scheduling policy: SCHED_OTHER Dec 17 23:17:17 musicbox volumio-cpu-tweak[984]: pid 35's current scheduling priority: 0 Dec 17 23:17:17 musicbox volumio-cpu-tweak[984]: Setting MPD Affinity Dec 17 23:17:17 musicbox volumio-cpu-tweak[984]: pid 3's current affinity mask: f Dec 17 23:17:17 musicbox volumio-cpu-tweak[984]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Dec 17 23:17:17 musicbox volumio-cpu-tweak[984]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Dec 17 23:17:17 musicbox dbus-daemon[583]: [system] Successfully activated service 'org.freedesktop.timedate1' Dec 17 23:17:17 musicbox systemd[1]: Started Time & Date Service. Dec 17 23:17:17 musicbox systemd[1]: volumio_cpu_tweak.service: Succeeded. Dec 17 23:17:41 musicbox systemd-timedated[976]: Changed local time to Wed Dec 17 23:17:41 2025 Dec 17 23:17:41 musicbox sudo[971]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:41 musicbox volumio-time-update[580]: volumio-time-update-util: System time updated successfully. Dec 17 23:17:41 musicbox systemd[1]: Started Volumio Time Update Utility. Dec 17 23:17:41 musicbox ntpd[753]: Listen normally on 3 wlan0 192.168.178.119:123 Dec 17 23:17:41 musicbox ntpd[753]: new interface(s) found: waking up resolver Dec 17 23:17:42 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:42] [info] asio async_connect error: system:111 (Connection refused) Dec 17 23:17:42 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:42] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Dec 17 23:17:42 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:42] [error] handle_connect error: Underlying Transport Error Dec 17 23:17:42 musicbox nmbd[736]: [2025/12/17 23:17:42.518957, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 17 23:17:42 musicbox systemd[1]: Started Samba NMB Daemon. Dec 17 23:17:42 musicbox nmbd[736]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Dec 17 23:17:42 musicbox systemd[1]: Starting Samba Winbind Daemon... Dec 17 23:17:43 musicbox winbindd[1000]: [2025/12/17 23:17:43.230674, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Dec 17 23:17:43 musicbox winbindd[1000]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Dec 17 23:17:43 musicbox winbindd[1000]: [2025/12/17 23:17:43.257869, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 17 23:17:43 musicbox winbindd[1000]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Dec 17 23:17:43 musicbox systemd[1]: Started Samba Winbind Daemon. Dec 17 23:17:43 musicbox systemd[1]: Starting Samba SMB Daemon... Dec 17 23:17:44 musicbox smbd[1005]: [2025/12/17 23:17:44.321402, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 17 23:17:44 musicbox systemd[1]: Started Samba SMB Daemon. Dec 17 23:17:44 musicbox smbd[1005]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Dec 17 23:17:44 musicbox systemd[1]: Reached target Multi-User System. Dec 17 23:17:44 musicbox systemd[1]: Reached target Graphical Interface. Dec 17 23:17:44 musicbox systemd[1]: Starting Shutdown Raspberry Pi after 60 minutes... Dec 17 23:17:44 musicbox systemd[1]: Starting Update UTMP about System Runlevel Changes... Dec 17 23:17:44 musicbox shutdown[1012]: Shutdown scheduled for Thu 2025-12-18 00:16:44 CET, use 'shutdown -c' to cancel. Dec 17 23:17:44 musicbox systemd[1]: Started Shutdown Raspberry Pi after 60 minutes. Dec 17 23:17:44 musicbox systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Dec 17 23:17:44 musicbox systemd[1]: Started Update UTMP about System Runlevel Changes. Dec 17 23:17:44 musicbox systemd[1]: Startup finished in 15.992s (kernel) + 34.119s (userspace) = 50.111s. Dec 17 23:17:45 musicbox systemd[1]: systemd-fsckd.service: Succeeded. Dec 17 23:17:45 musicbox volumio[983]: info: ------------------------------------------- Dec 17 23:17:45 musicbox volumio[983]: info: ----- Volumio3 ---- Dec 17 23:17:45 musicbox volumio[983]: info: ------------------------------------------- Dec 17 23:17:45 musicbox volumio[983]: info: ----- System startup ---- Dec 17 23:17:45 musicbox volumio[983]: info: ------------------------------------------- Dec 17 23:17:48 musicbox volumio[983]: info: MYVOLUMIO Environment detected Dec 17 23:17:48 musicbox volumio[983]: info: Plugin folders cleanup Dec 17 23:17:48 musicbox volumio[983]: info: Scanning into folder /volumio/app/plugins/ Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category audio_interface Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category miscellanea Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category music_service Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category plugins.json Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category system_controller Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category user_interface Dec 17 23:17:48 musicbox volumio[983]: info: Scanning into folder /data/plugins/ Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category music_service Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category system_controller Dec 17 23:17:48 musicbox volumio[983]: info: Scanning category system_hardware Dec 17 23:17:48 musicbox volumio[983]: info: Plugin folders cleanup completed Dec 17 23:17:48 musicbox volumio[983]: info: ------------------------------------------- Dec 17 23:17:48 musicbox volumio[983]: info: ----- Core plugins startup ---- Dec 17 23:17:48 musicbox volumio[983]: info: ------------------------------------------- Dec 17 23:17:48 musicbox volumio[983]: info: Loading plugins from folder /volumio/app/plugins/ Dec 17 23:17:48 musicbox volumio[983]: info: Adding plugin upnp to MyMusic Plugins Dec 17 23:17:48 musicbox volumio[983]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 17 23:17:48 musicbox volumio[983]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 17 23:17:48 musicbox volumio[983]: info: Loading plugins from folder /data/plugins/ Dec 17 23:17:48 musicbox volumio[983]: info: Loading plugin "system"... Dec 17 23:17:48 musicbox volumio[983]: info: Loading plugin "appearance"... Dec 17 23:17:49 musicbox sh[565]: timed out Dec 17 23:17:49 musicbox dhcpcd[586]: timed out Dec 17 23:17:49 musicbox sh[565]: dhcpcd exited Dec 17 23:17:49 musicbox dhcpcd[586]: dhcpcd exited Dec 17 23:17:49 musicbox sh[565]: ifup: failed to bring up eth0 Dec 17 23:17:49 musicbox systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Dec 17 23:17:49 musicbox systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "network"... Dec 17 23:17:51 musicbox volumio[983]: info: Refreshing Cached IP Addresses Dec 17 23:17:51 musicbox sudo[1030]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 17 23:17:51 musicbox sudo[1030]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:51 musicbox sudo[1032]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 17 23:17:51 musicbox sudo[1032]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:51 musicbox sudo[1030]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:51 musicbox sudo[1032]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "services"... Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "alsa_controller"... Dec 17 23:17:51 musicbox sudo[1041]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 17 23:17:51 musicbox sudo[1041]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:51 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "wizard"... Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "networkfs"... Dec 17 23:17:51 musicbox volumio[983]: info: Starting Udev Watcher for removable devices Dec 17 23:17:51 musicbox sudo[1058]: 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 Dec 17 23:17:51 musicbox sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:17:51 musicbox volumio[983]: info: Ignoring mount for partition: boot Dec 17 23:17:51 musicbox volumio[983]: info: Ignoring mount for partition: volumio Dec 17 23:17:51 musicbox volumio[983]: info: Ignoring mount for partition: volumio_data Dec 17 23:17:51 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "volumio_command_line_client"... Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "upnp"... Dec 17 23:17:51 musicbox volumio[983]: info: [1766009871909] Starting Upmpd Daemon Dec 17 23:17:51 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "my_music"... Dec 17 23:17:51 musicbox volumio[983]: info: Loading plugin "mpd"... Dec 17 23:17:52 musicbox systemd[1]: systemd-hostnamed.service: Succeeded. Dec 17 23:17:52 musicbox kernel: Key type cifs.spnego registered Dec 17 23:17:52 musicbox kernel: Key type cifs.idmap registered Dec 17 23:17: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. Dec 17 23:17:52 musicbox kernel: CIFS: Attempting to mount //se-se01/internal/music Dec 17 23:17:52 musicbox volumio-remote-updater[592]: [2025-12-17 23:17:52] [connect] Successful connection Dec 17 23:17:52 musicbox kernel: cryptd: max_cpu_qlen set to 1000 Dec 17 23:17:52 musicbox kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE Dec 17 23:17:52 musicbox kernel: CIFS: VFS: \\se-se01 Send error in SessSetup = -13 Dec 17 23:17:52 musicbox kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Dec 17 23:17:52 musicbox sudo[1058]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:53 musicbox volumio[983]: info: Loading plugin "upnp_browser"... Dec 17 23:17:53 musicbox volumio[983]: info: Loading plugin "alarm-clock"... Dec 17 23:17:54 musicbox volumio[983]: info: Loading plugin "airplay_emulation"... Dec 17 23:17:54 musicbox volumio[983]: info: Starting Shairport Sync Dec 17 23:17:54 musicbox volumio[983]: info: Loading plugin "last_100"... Dec 17 23:17:54 musicbox volumio[983]: info: Loading plugin "webradio"... Dec 17 23:17:54 musicbox sudo[1041]: pam_unix(sudo:session): session closed for user root Dec 17 23:17:54 musicbox volumio[983]: info: Loading plugin "i2s_dacs"... Dec 17 23:17:54 musicbox volumio[983]: info: Loading plugin "volumiodiscovery"... Dec 17 23:17:54 musicbox volumio[983]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 17 23:17:54 musicbox volumio[983]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 17 23:17:54 musicbox volumio[983]: *** WARNING *** For more information see Dec 17 23:17:54 musicbox node[983]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 17 23:17:54 musicbox volumio[983]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 17 23:17:54 musicbox volumio[983]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 17 23:17:54 musicbox volumio[983]: *** WARNING *** For more information see Dec 17 23:17:54 musicbox node[983]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 17 23:17:54 musicbox node[983]: *** WARNING *** For more information see Dec 17 23:17:54 musicbox node[983]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 17 23:17:54 musicbox node[983]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 17 23:17:54 musicbox node[983]: *** WARNING *** For more information see Dec 17 23:17:54 musicbox volumio[983]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 17 23:17:54 musicbox volumio[983]: info: Discovery: Started advertising with name: MusicBox Dec 17 23:17:54 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 17 23:17:54 musicbox volumio[983]: info: Loading plugin "spop"... Dec 17 23:17:57 musicbox volumio[983]: info: Loading plugin "ytcr"... Dec 17 23:18:07 musicbox volumio[983]: info: Loading plugin "autostart"... Dec 17 23:18:07 musicbox volumio-remote-updater[592]: [2025-12-17 23:18:07] [connect] Successful connection Dec 17 23:18:07 musicbox volumio[983]: info: Applying required configuration parameters for plugin autostart Dec 17 23:18:07 musicbox volumio[983]: info: AutoStart - onVolumioStart - read config.json Dec 17 23:18:07 musicbox volumio[983]: info: Loading plugin "outputs"... Dec 17 23:18:07 musicbox volumio[983]: info: Loading plugin "albumart"... Dec 17 23:18:07 musicbox volumio[983]: info: Plugin example_plugin is not enabled Dec 17 23:18:07 musicbox volumio[983]: info: Loading plugin "inputs"... Dec 17 23:18:07 musicbox volumio[983]: info: Loading plugin "updater_comm"... Dec 17 23:18:08 musicbox volumio[983]: info: Plugin mpdemulation is not enabled Dec 17 23:18:08 musicbox volumio[983]: info: Loading plugin "rest_api"... Dec 17 23:18:08 musicbox volumio[983]: info: Loading plugin "websocket"... Dec 17 23:18:08 musicbox volumio[983]: info: Starting Socket.io Server version 2.3.0 Dec 17 23:18:08 musicbox volumio[983]: info: Loading plugin "backup_restore"... Dec 17 23:18:08 musicbox volumio[983]: Forking 3 albumart workers Dec 17 23:18:08 musicbox volumio[983]: info: Applying required configuration parameters for plugin backup_restore Dec 17 23:18:08 musicbox volumio[983]: info: Loading plugin "rotaryencoder2"... Dec 17 23:18:09 musicbox volumio[983]: info: Loading i18n strings for locale de Dec 17 23:18:09 musicbox volumio[983]: Updating browse sources language Dec 17 23:18:09 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 17 23:18:10 musicbox volumio[983]: Starting albumart workers Dec 17 23:18:10 musicbox volumio[983]: Starting albumart workers Dec 17 23:18:10 musicbox volumio[983]: Starting albumart workers Dec 17 23:18:10 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 17 23:18:10 musicbox volumio[983]: info: CoreCommandRouter::initPlayerControls Dec 17 23:18:10 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:10 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 17 23:18:10 musicbox volumio[983]: Express server listening on port 3000 Dec 17 23:18:10 musicbox volumio[983]: [Metrics] WebUI: 26s 141.38ms Dec 17 23:18:10 musicbox volumio[983]: info: CoreStateMachine::resetVolumioState Dec 17 23:18:10 musicbox volumio[983]: info: CoreStateMachine::getcurrentVolume Dec 17 23:18:10 musicbox volumio[983]: info: CoreCommandRouter::volumioRetrievevolume Dec 17 23:18:10 musicbox sudo[1147]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 17 23:18:10 musicbox sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:10 musicbox sudo[1147]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:10 musicbox sudo[1149]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 17 23:18:10 musicbox sudo[1149]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:10 musicbox volumio[983]: info: Volumio Network Manager: Network status updated: 2 Dec 17 23:18:10 musicbox sudo[1149]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:10 musicbox volumio[983]: info: Cannot mount NAS Musik at system boot, trial number 1 ,retrying in 5 seconds Dec 17 23:18:11 musicbox systemd[1]: systemd-timedated.service: Succeeded. Dec 17 23:18:11 musicbox volumio-remote-updater[592]: [2025-12-17 23:18:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1766009887 101 Dec 17 23:18:11 musicbox volumio[983]: 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 Dec 17 23:18:11 musicbox volumio[983]: info: VolumeController:: Volume=30 Mute =false Dec 17 23:18:11 musicbox volumio[983]: info: CoreStateMachine::pushState Dec 17 23:18:11 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::volumioPushState Dec 17 23:18:11 musicbox volumio[983]: info: CoreStateMachine::updateTrackBlock Dec 17 23:18:11 musicbox volumio[983]: info: CorePlayQueue::getTrackBlock Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::volumioRetrievevolume Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 23:18:11 musicbox volumio[983]: info: Executing start script for DAC IQaudIO DAC Plus Dec 17 23:18:11 musicbox volumio[983]: info: Reloading queue from file Dec 17 23:18:11 musicbox volumio[983]: info: CoreStateMachine::setRepeat true single undefined Dec 17 23:18:11 musicbox volumio[983]: info: CoreStateMachine::pushState Dec 17 23:18:11 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::volumioPushState Dec 17 23:18:11 musicbox volumio[983]: info: CoreStateMachine::setRandom true Dec 17 23:18:11 musicbox volumio[983]: info: CoreStateMachine::pushState Dec 17 23:18:11 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::volumioPushState Dec 17 23:18:11 musicbox volumio[983]: info: Setting Device type: Raspberry PI Dec 17 23:18:11 musicbox volumio[983]: info: DAC script executed Dec 17 23:18:11 musicbox volumio[983]: info: Completed loading Core Plugins Dec 17 23:18:11 musicbox volumio[983]: info: Preparing to generate the ALSA configuration file Dec 17 23:18:11 musicbox volumio[983]: info: VolumeController:: Volume=30 Mute =false Dec 17 23:18:11 musicbox volumio[983]: info: CoreStateMachine::pushState Dec 17 23:18:11 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::volumioPushState Dec 17 23:18:11 musicbox volumio[983]: info: Discovery: adding 95307504-9fd1-4df0-a09a-bb5004682349 Dec 17 23:18:11 musicbox volumio[983]: info: Discovery: Found device MusicBox Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::volumioGetState Dec 17 23:18:11 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:11 musicbox volumio[983]: info: Asound.conf file unchanged, so no further update is needed Dec 17 23:18:11 musicbox volumio[983]: info: Output device has changed, restarting MPD Dec 17 23:18:11 musicbox sudo[1205]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 17 23:18:11 musicbox sudo[1205]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:11 musicbox sudo[1208]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 17 23:18:11 musicbox sudo[1208]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:11 musicbox volumio[983]: info: Output device has changed, restarting Shairport Sync Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:11 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 23:18:11 musicbox sudo[1208]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:12 musicbox systemd[1]: Started UPnP Renderer front-end to MPD. Dec 17 23:18:12 musicbox sudo[1210]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 17 23:18:12 musicbox sudo[1210]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:12 musicbox sudo[1205]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:12 musicbox systemd[1]: Listening on mpd.socket. Dec 17 23:18:12 musicbox volumio[983]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 17 23:18:12 musicbox systemd[1]: Starting Music Player Daemon... Dec 17 23:18:12 musicbox volumio[983]: info: ___________ START PLUGINS ___________ Dec 17 23:18:12 musicbox volumio[983]: info: ControllerMpd::onStart: Initializing MPD Dec 17 23:18:12 musicbox volumio[983]: info: Creating MPD Configuration file Dec 17 23:18:12 musicbox sudo[1220]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 17 23:18:12 musicbox sudo[1220]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 17 23:18:12 musicbox volumio[983]: info: [1766009892218] CoreMusicLibrary::Adding element Medienserver Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 17 23:18:12 musicbox sudo[1220]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:12 musicbox sudo[1222]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 17 23:18:12 musicbox sudo[1222]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 23:18:12 musicbox systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Dec 17 23:18:12 musicbox systemd[1]: mpd.service: Succeeded. Dec 17 23:18:12 musicbox systemd[1]: Stopped Music Player Daemon. Dec 17 23:18:12 musicbox volumio[983]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 23:18:12 musicbox systemd[1]: Starting Music Player Daemon... Dec 17 23:18:12 musicbox volumio[983]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 17 23:18:12 musicbox volumio[983]: info: [1766009892467] CoreMusicLibrary::Adding element Last_100 Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 17 23:18:12 musicbox volumio[983]: info: [1766009892473] CoreMusicLibrary::Adding element Webradio Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 17 23:18:12 musicbox volumio[983]: info: Initializing BBC Radios Dec 17 23:18:12 musicbox sudo[1228]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 17 23:18:12 musicbox sudo[1228]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 23:18:12 musicbox sudo[1228]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 17 23:18:12 musicbox sudo[1228]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:12 musicbox volumio[983]: info: Creating Spotify config file Dec 17 23:18:12 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:12 musicbox volumio[983]: info: AutoStart - onStart Dec 17 23:18:12 musicbox volumio[983]: info: [ROTARYENCODER2] loadI18nStrings: /data/plugins/system_hardware/rotaryencoder2/i18n/strings_de.json Dec 17 23:18:12 musicbox volumio[983]: info: [ROTARYENCODER2] loadI18nStrings: loaded: Dec 17 23:18:12 musicbox volumio[983]: info: [ROTARYENCODER2] onStart: Config loaded: Dec 17 23:18:13 musicbox volumio[983]: info: [ROTARYENCODER2] installAllOverlays: 1,2,3 Dec 17 23:18:13 musicbox volumio[983]: info: [ROTARYENCODER2] installAllOverlays: 1,2 Dec 17 23:18:13 musicbox volumio[983]: info: [ROTARYENCODER2] installAllOverlays: 1 Dec 17 23:18:13 musicbox volumio[983]: info: [ROTARYENCODER2] installAllOverlays: Dec 17 23:18:13 musicbox volumio[983]: info: [ROTARYENCODER2] installAllOverlays: end of recursion. Dec 17 23:18:13 musicbox volumio[983]: info: Volumio Calling Home Dec 17 23:18:13 musicbox volumio[983]: info: [ROTARYENCODER2] addOverlay for Rotary: 23 27 1 Dec 17 23:18:13 musicbox volumio[983]: 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 & Dec 17 23:18:13 musicbox sudo[1248]: 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 Dec 17 23:18:13 musicbox sudo[1248]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:13 musicbox volumio[983]: info: MPD Permissions set Dec 17 23:18:13 musicbox volumio[983]: info: Upmpdcli Daemon Started Dec 17 23:18:13 musicbox volumio[983]: info: Spotify config file written Dec 17 23:18:13 musicbox kernel: rotary-encoder rotary@17: gray Dec 17 23:18:13 musicbox kernel: input: rotary@17 as /devices/platform/rotary@17/input/input0 Dec 17 23:18:13 musicbox sudo[1258]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 17 23:18:13 musicbox sudo[1258]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:13 musicbox sudo[1248]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:13 musicbox volumio[983]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 17 23:18:13 musicbox volumio[983]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 17 23:18:13 musicbox volumio[983]: info: Volumio called home Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox systemd[1]: Started go-librespot Daemon. Dec 17 23:18:13 musicbox go-librespot[1265]: go-librespot daemon starting... Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox sudo[1258]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 23:18:13 musicbox volumio[983]: info: No need to fix Spotify hosts Dec 17 23:18:13 musicbox systemd-udevd[1255]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Dec 17 23:18:14 musicbox volumio[983]: info: /dev/input: Dec 17 23:18:14 musicbox volumio[983]: by-path Dec 17 23:18:14 musicbox volumio[983]: event0 Dec 17 23:18:14 musicbox volumio[983]: mice Dec 17 23:18:14 musicbox volumio[983]: /dev/input/by-path: Dec 17 23:18:14 musicbox volumio[983]: platform-rotary@17-event Dec 17 23:18:14 musicbox volumio[983]: info: Starting Shairport Sync Dec 17 23:18:14 musicbox volumio[983]: info: Starting Shairport Sync Dec 17 23:18:14 musicbox volumio[983]: info: Starting Shairport Sync Dec 17 23:18:14 musicbox sudo[1285]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 17 23:18:14 musicbox sudo[1285]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:14 musicbox volumio[983]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 17 23:18:14 musicbox volumio[983]: SPOTIFY: BQBfr1_jsjKAJ8KPnwiQe0HiRbXYv7uNr2v6rXq2QC3WSB-r6AEUl1Cpl7J_420zKdSzbaX0djaF_V2tpV-IdehkPQtbzh_J-qTEjYUbSbqiScwSadaINhCZ7yUFkxIrMHXSD2qsQ6htc1c5d9bxdbcG3XqTI0lwTPzqqg7V1UTmASFdSrxNzVNjACnhaTFqDJJe5g4VlczR9HjkwhsLQcdKuI9mwbu_Cdy2tVOY8vhYjiUxEoXza9kNISx5fN9dgnlcHaQ-IIPux1AKKpdo2j3QppfaBe7TmXevE214qMYRtnW9DL3kgwSTNmKy Dec 17 23:18:14 musicbox volumio[983]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 17 23:18:14 musicbox volumio[983]: info: New Spotify access token = BQBfr1_jsjKAJ8KPnwiQe0HiRbXYv7uNr2v6rXq2QC3WSB-r6AEUl1Cpl7J_420zKdSzbaX0djaF_V2tpV-IdehkPQtbzh_J-qTEjYUbSbqiScwSadaINhCZ7yUFkxIrMHXSD2qsQ6htc1c5d9bxdbcG3XqTI0lwTPzqqg7V1UTmASFdSrxNzVNjACnhaTFqDJJe5g4VlczR9HjkwhsLQcdKuI9mwbu_Cdy2tVOY8vhYjiUxEoXza9kNISx5fN9dgnlcHaQ-IIPux1AKKpdo2j3QppfaBe7TmXevE214qMYRtnW9DL3kgwSTNmKy Dec 17 23:18:14 musicbox volumio[983]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 17 23:18:14 musicbox sudo[1290]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 17 23:18:14 musicbox sudo[1287]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 17 23:18:14 musicbox sudo[1287]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:14 musicbox sudo[1290]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:14 musicbox systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Dec 17 23:18:14 musicbox go-librespot[1265]: time="2025-12-17T23:18:14+01:00" level=info msg="running go-librespot 0.4.0" Dec 17 23:18:14 musicbox systemd[1]: shairport-sync.service: Succeeded. Dec 17 23:18:14 musicbox systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Dec 17 23:18:14 musicbox go-librespot[1265]: time="2025-12-17T23:18:14+01:00" level=debug msg="app state loaded" Dec 17 23:18:14 musicbox volumio[983]: info: CoreCommandRouter::volumioGetState Dec 17 23:18:14 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:14 musicbox go-librespot[1265]: time="2025-12-17T23:18:14+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 17 23:18:14 musicbox volumio[983]: info: CoreCommandRouter::volumioGetState Dec 17 23:18:14 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:14 musicbox systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Dec 17 23:18:14 musicbox sudo[1285]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:14 musicbox systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Dec 17 23:18:14 musicbox systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Dec 17 23:18:14 musicbox systemd[1]: shairport-sync.service: Succeeded. Dec 17 23:18:14 musicbox systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Dec 17 23:18:14 musicbox systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Dec 17 23:18:14 musicbox sudo[1290]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:14 musicbox volumio[983]: info: Shairport-Sync Started Dec 17 23:18:14 musicbox sudo[1287]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:14 musicbox volumio[983]: Error adding Membership: Error: addMembership EINVAL Dec 17 23:18:14 musicbox volumio[983]: info: Shairport-Sync Started Dec 17 23:18:14 musicbox volumio[983]: info: Shairport-Sync Started Dec 17 23:18:15 musicbox volumio[983]: SPOTIFY: User informations: {"country":"IN","display_name":"Lukas Trausch","email":"management@gipfelnovation.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/ab6775700000ee85c78e14e5de121b3a5a19cc70","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82c78e14e5de121b3a5a19cc70","width":64}],"product":"premium","type":"user","uri":"spotify:user:31bjkbz74djgmahibcw3dkhb6sha"} Dec 17 23:18:15 musicbox volumio[983]: info: Spotify Successfully logged in Dec 17 23:18:15 musicbox volumio[983]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 17 23:18:15 musicbox volumio[983]: info: [1766009895038] CoreMusicLibrary::Adding element Spotify Dec 17 23:18:15 musicbox volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 17 23:18:15 musicbox volumio[983]: Cannot find translation for source Spotify Dec 17 23:18:15 musicbox volumio[983]: info: [ROTARYENCODER2] addOverlay for Button: 4 true up Dec 17 23:18:15 musicbox volumio[983]: info: [ROTARYENCODER2] addOverlay: executing command: /usr/bin/sudo /usr/bin/dtoverlay gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 & Dec 17 23:18:15 musicbox sudo[1298]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 Dec 17 23:18:15 musicbox sudo[1298]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:15 musicbox kernel: input: button@4 as /devices/platform/button@4/input/input1 Dec 17 23:18:15 musicbox sudo[1298]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:15 musicbox volumio[983]: info: /dev/input: Dec 17 23:18:15 musicbox volumio[983]: by-path Dec 17 23:18:15 musicbox volumio[983]: event0 Dec 17 23:18:15 musicbox volumio[983]: event1 Dec 17 23:18:15 musicbox volumio[983]: mice Dec 17 23:18:15 musicbox volumio[983]: /dev/input/by-path: Dec 17 23:18:15 musicbox volumio[983]: platform-rotary@17-event Dec 17 23:18:15 musicbox go-librespot[1265]: time="2025-12-17T23:18:15+01: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]" Dec 17 23:18:15 musicbox go-librespot[1265]: time="2025-12-17T23:18:15+01: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]" Dec 17 23:18:15 musicbox go-librespot[1265]: time="2025-12-17T23:18:15+01: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]" Dec 17 23:18:15 musicbox go-librespot[1265]: time="2025-12-17T23:18:15+01:00" level=info msg="zeroconf server listening on port 44487" Dec 17 23:18:15 musicbox systemd-udevd[1255]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Dec 17 23:18:15 musicbox go-librespot[1265]: time="2025-12-17T23:18:15+01:00" level=debug msg="obtained new client token: AADJzuZ4a6tcrhvNc3Li7Ucne81K36mLRU87wpa22Am7s7CigfKo4iw7rb2CrFNBoMHBV/fhBSs+Rbc46RRq4idJDFknejKOUDdb1hdu4RWFsjtY3Xd7nM/lSa+1PhPDN++5MXrAUGy+2crIKsI7wac9E3r44bvCpXa5BRL7zX+/TdAxO5KHEzqo44YSBWlMgCxoEgbuOe3lm4fyKfe3iWDsF1Ylu4coGpbNPD/Ou8xfHVillknfVvZiNg==" Dec 17 23:18:15 musicbox volumio[983]: info: [yt-cast-receiver] DIAL server listening on port 8098 Dec 17 23:18:15 musicbox sudo[1312]: 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 Dec 17 23:18:15 musicbox sudo[1312]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:15 musicbox volumio[983]: info: CoreCommandRouter::volumioRetrievevolume Dec 17 23:18:15 musicbox go-librespot[1265]: time="2025-12-17T23:18:15+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 17 23:18:15 musicbox kernel: CIFS: Attempting to mount //se-se01/internal/music Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="completed keyexchange" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="completed challenge" Dec 17 23:18:16 musicbox volumio[983]: info: VolumeController:: Volume=30 Mute =false Dec 17 23:18:16 musicbox volumio[983]: info: CoreCommandRouter::volumioGetState Dec 17 23:18:16 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:16 musicbox volumio[983]: info: CoreStateMachine::pushState Dec 17 23:18:16 musicbox volumio[983]: info: CorePlayQueue::getTrack 0 Dec 17 23:18:16 musicbox volumio[983]: info: CoreCommandRouter::volumioPushState Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=info msg="authenticated AP" username="31************************ha" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=info msg="authenticated Login5" username="31************************ha" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="initializing zeroconf session" username="31************************ha" Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners: 1,2,3 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners: 1,2 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners: 1 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners: Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners: end of recursion. Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] checkOverlayExists: Checking for existing overlays for Rotary: 1 type: rotary Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="dealer connection opened" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=trace msg="starting accesspoint recv loop" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=trace msg="starting dealer recv loop" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=trace msg="received accesspoint ping" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="received connection id: MjFkMDg4YjktZjUy...MzdEMENCODM5MQ==" Dec 17 23:18:16 musicbox sudo[1320]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=trace msg="received accesspoint pong ack" Dec 17 23:18:16 musicbox sudo[1320]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:16 musicbox sudo[1320]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] checkOverlayExists: check pinA=23pinB=27 in Overlays (in load order): Dec 17 23:18:16 musicbox volumio[983]: 0: rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 Dec 17 23:18:16 musicbox volumio[983]: 1: gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] checkOverlayExists: rotary 1 uses overlay 0 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners: attach rotary 1 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachListener: path: /dev/input/by-path/platform-rotary@17-event, type: rotary Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] checkOverlayExists: Checking for existing overlays for Rotary: 1 type: button Dec 17 23:18:16 musicbox sudo[1324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Dec 17 23:18:16 musicbox sudo[1324]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 17 23:18:16 musicbox sudo[1324]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] checkOverlayExists: check pinA=4pinB=undefined in Overlays (in load order): Dec 17 23:18:16 musicbox volumio[983]: 0: rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 Dec 17 23:18:16 musicbox volumio[983]: 1: gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] checkOverlayExists: button 1 uses overlay 1 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners: attach button 1 Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachListener: path: /dev/input/by-path/platform-button@4-event, type: button Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners rotaries: Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners buttons: Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners rotaries: Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] attachAllListeners buttons: Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] onStart: Attach Event-handles now. Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] Now addAllEventHandles for rotaries. Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] addEventHandle for rotary: 1 type: rotary Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] Now addAllEventHandles for buttons. Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] addEventHandle for rotary: 1 type: button Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] addEventHandle: adding handle : Dec 17 23:18:16 musicbox volumio[983]: info: [ROTARYENCODER2] onStart: Plugin successfully started. Dec 17 23:18:16 musicbox go-librespot[1265]: time="2025-12-17T23:18:16+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 17 23:18:17 musicbox volumio[983]: info: go-librespot daemon successfully initialized Dec 17 23:18:17 musicbox go-librespot[1265]: time="2025-12-17T23:18:17+01:00" level=debug msg="handling transfer player command from e7b5a8ca8ddad5f4f57fa3bdac27afc15fe4a966" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:7uDbT77PcK6bu54y3jMTHx" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=trace msg="fetched new page 0 with 48 items (list: 48)" uri="spotify:playlist:7uDbT77PcK6bu54y3jMTHx" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="shuffled context with seed 6305343163192518587 (len: 48, keep: 17)" uri="spotify:playlist:7uDbT77PcK6bu54y3jMTHx" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="loading track (paused: true, position: 54167ms)" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 310" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=trace msg="emitting websocket event: will_play" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1715" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="selected format OGG_VORBIS_160 (87858c8d908a49cf31bcc3aec5a2ed0ef3a36647)" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="requested aes key for file 87858c8d908a49cf31bcc3aec5a2ed0ef3a36647, gid: 39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:18 musicbox mpd[1243]: Dec 17 23:18 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 17 23:18:18 musicbox systemd[1]: Started Music Player Daemon. Dec 17 23:18:18 musicbox go-librespot[1265]: time="2025-12-17T23:18:18+01:00" level=debug msg="fetched first chunk of 9, total size is 4413676 bytes" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:18 musicbox sudo[1210]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:18 musicbox sudo[1222]: pam_unix(sudo:session): session closed for user root Dec 17 23:18:18 musicbox volumio[983]: Upnp client error: Error: This socket has been ended by the other party Dec 17 23:18:18 musicbox volumio[983]: Upnp client error: Error: This socket has been ended by the other party Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="fetched chunk 1/8, size: 524288" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:19 musicbox volumio[983]: error: MPD error: The expression evaluated to a falsy value: Dec 17 23:18:19 musicbox volumio[983]: assert.ok(self.idling) Dec 17 23:18:19 musicbox volumio[983]: error: The expression evaluated to a falsy value: Dec 17 23:18:19 musicbox volumio[983]: assert.ok(self.idling) Dec 17 23:18:19 musicbox volumio[983]: info: MPD running with PID1243 Dec 17 23:18:19 musicbox volumio[983]: ,establishing connection Dec 17 23:18:19 musicbox volumio[983]: error: updateQueue error: null Dec 17 23:18:19 musicbox volumio[983]: error: updateQueue error: null Dec 17 23:18:19 musicbox volumio[983]: info: Completed starting Core Plugins Dec 17 23:18:19 musicbox volumio[983]: info: ------------------------------------------- Dec 17 23:18:19 musicbox volumio[983]: info: ----- MyVolumio plugins startup ---- Dec 17 23:18:19 musicbox volumio[983]: info: ------------------------------------------- Dec 17 23:18:19 musicbox volumio[983]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="fetched chunk 3/8, size: 524288" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="fetched chunk 2/8, size: 524288" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=trace msg="seek to 54167ms (diff: 53735ms, samples: 2388764, bytes: 1067326)" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="created new output device" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=info msg="loaded track \"An Angel\" (paused: true, position: 54167ms, duration: 224506ms, prefetched: false)" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="fetched chunk 4/8, size: 524288" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="fetched chunk 5/8, size: 524288" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=trace msg="emitting websocket event: metadata" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=trace msg="emitting websocket event: active" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="sending successful reply for dealer request" Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 17 23:18:19 musicbox go-librespot[1265]: time="2025-12-17T23:18:19+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=trace msg="emitting websocket event: paused" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=debug msg="handling resume player command from e7b5a8ca8ddad5f4f57fa3bdac27afc15fe4a966" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=trace msg="seek to 54167ms (diff: 46ms, samples: 2388764, bytes: 1067326)" uri="spotify:track:39tA7koBZwRzaes3ffpGz7" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01: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, PCM format = FLOAT_LE" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=debug msg="resume track at 54121ms" Dec 17 23:18:20 musicbox volumio[983]: info: Initializing connection to go-librespot Websocket Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=debug msg="new websocket client" Dec 17 23:18:20 musicbox volumio[983]: info: Connection to go-librespot Websocket established Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=trace msg="scheduling prefetch in 140s" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=debug msg="sending successful reply for dealer request" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 23:18:20 musicbox go-librespot[1265]: time="2025-12-17T23:18:20+01:00" level=trace msg="emitting websocket event: playing" Dec 17 23:18:20 musicbox volumio[983]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:7uDbT77PcK6bu54y3jMTHx","uri":"spotify:track:39tA7koBZwRzaes3ffpGz7","resume":true,"play_origin":"playlist"}} Dec 17 23:18:20 musicbox volumio[983]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 17 23:18:20 musicbox volumio[983]: TypeError: Cannot read property 'service' of undefined Dec 17 23:18:20 musicbox volumio[983]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 17 23:18:20 musicbox volumio[983]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Dec 17 23:18:20 musicbox volumio[983]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 17 23:18:20 musicbox volumio[983]: at WebSocket.emit (events.js:315:20) Dec 17 23:18:20 musicbox volumio[983]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 17 23:18:20 musicbox volumio[983]: at Receiver.emit (events.js:315:20) Dec 17 23:18:20 musicbox volumio[983]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 17 23:18:20 musicbox volumio[983]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 17 23:18:20 musicbox volumio[983]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 17 23:18:20 musicbox volumio[983]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 17 23:18:20 musicbox volumio[983]: at writeOrBuffer (internal/streams/writable.js:358:12) Dec 17 23:18:20 musicbox volumio[983]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Dec 17 23:18:20 musicbox volumio[983]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 17 23:18:20 musicbox volumio[983]: at Socket.emit (events.js:315:20) Dec 17 23:18:20 musicbox volumio[983]: at addChunk (internal/streams/readable.js:309:12) Dec 17 23:18:20 musicbox volumio[983]: at readableAddChunk (internal/streams/readable.js:284:9) Dec 17 23:18:20 musicbox volumio[983]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 17 23:18:21 musicbox sudo[1393]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-17 23:17 Dec 17 23:18:21 musicbox sudo[1393]: 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="cc50ad4a2058d01de272214eb33827883bd2b7d8" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="502750e5d54ecf269d25125b622bfabc030fb553" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 12 Nov 2025 06:58:02 PM CET" VOLUMIO_VERSION="3.874" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4ae6504ed6f22e44c01a6e93b16badbd"