-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Wed 2025-03-12 18:18:38 CET. -- Mar 12 18:18:11 volumio systemd-timedated[941]: Changed local time to Wed Mar 12 18:18:11 2025 Mar 12 18:18:11 volumio sudo[922]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:11 volumio volumio-time-update[612]: volumio-time-update-util: System time updated successfully. Mar 12 18:18:11 volumio systemd[1]: Started Volumio Time Update Utility. Mar 12 18:18:11 volumio systemd[1]: Starting Daily apt download activities... Mar 12 18:18:11 volumio dhcpcd-run-hooks[948]: wlan0: failed to start wpa_supplicant Mar 12 18:18:11 volumio dhcpcd-run-hooks[949]: 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 Mar 12 18:18:11 volumio dhcpcd[932]: wlan0: connected to Access Point `' Mar 12 18:18:11 volumio dhcpcd[932]: DUID 00:01:00:01:2e:f2:a2:d7:b8:27:eb:be:da:0c Mar 12 18:18:11 volumio dhcpcd[932]: eth0: IAID eb:be:da:0c Mar 12 18:18:11 volumio dhcpcd[932]: eth0: adding address fe80::47e1:95cc:3b15:96bd Mar 12 18:18:11 volumio dhcpcd[932]: ipv6_addaddr1: Permission denied Mar 12 18:18:11 volumio dhcpcd[932]: wlan0: waiting for carrier Mar 12 18:18:11 volumio dhcpcd[932]: eth0: soliciting an IPv6 router Mar 12 18:18:11 volumio mpd[819]: Mar 12 18:18 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 12 18:18:11 volumio dhcpcd[932]: eth0: rebinding lease of 10.0.0.231 Mar 12 18:18:11 volumio systemd[1]: Started Music Player Daemon. Mar 12 18:18:11 volumio mpd_monitor.sh[608]: MPD Monitor Service: MPD restarted due to no mpc output. Mar 12 18:18:11 volumio dhcpcd[932]: eth0: leased 10.0.0.231 for 86400 seconds Mar 12 18:18:11 volumio dhcpcd[932]: eth0: adding route to 10.0.0.0/24 Mar 12 18:18:11 volumio dhcpcd[932]: eth0: adding default route via 10.0.0.1 Mar 12 18:18:11 volumio wpa_supplicant[946]: wlan0: Trying to associate with SSID 'Martin Router King' Mar 12 18:18:11 volumio dhcpcd[932]: forked to background, child pid 997 Mar 12 18:18:11 volumio sudo[931]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:11 volumio wireless.js[601]: trying... Mar 12 18:18:11 volumio sudo[1005]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 18:18:11 volumio sudo[1005]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:11 volumio sudo[1005]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:11 volumio dhcpcd[997]: wlan0: carrier acquired Mar 12 18:18:11 volumio dhcpcd[997]: wlan0: connected to Access Point `Martin Router King' Mar 12 18:18:11 volumio wpa_supplicant[946]: wlan0: Associated with e6:63:da:ad:fb:d1 Mar 12 18:18:11 volumio wpa_supplicant[946]: wlan0: CTRL-EVENT-CONNECTED - Connection to e6:63:da:ad:fb:d1 completed [id=0 id_str=] Mar 12 18:18:11 volumio wpa_supplicant[946]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 12 18:18:11 volumio wpa_supplicant[946]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Mar 12 18:18:11 volumio dhcpcd[997]: wlan0: IAID eb:eb:8f:59 Mar 12 18:18:11 volumio dhcpcd[997]: wlan0: adding address fe80::8c1b:fa04:9fe4:690e Mar 12 18:18:11 volumio dhcpcd[997]: ipv6_addaddr1: Permission denied Mar 12 18:18:11 volumio dhcpcd[997]: wlan0: carrier lost Mar 12 18:18:11 volumio dhcpcd[997]: wlan0: carrier acquired Mar 12 18:18:11 volumio dhcpcd[997]: wlan0: IAID eb:eb:8f:59 Mar 12 18:18:12 volumio dhcpcd[997]: wlan0: soliciting an IPv6 router Mar 12 18:18:12 volumio dhcpcd[997]: wlan0: rebinding lease of 10.0.0.244 Mar 12 18:18:12 volumio dhcpcd[997]: wlan0: probing address 10.0.0.244/24 Mar 12 18:18:12 volumio wireless.js[601]: trying... Mar 12 18:18:12 volumio sudo[1035]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 18:18:12 volumio sudo[1035]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:12 volumio sudo[1035]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:12 volumio nmbd[743]: [2025/03/12 18:18:12.985702, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 12 18:18:12 volumio nmbd[743]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Mar 12 18:18:12 volumio systemd[1]: Started Samba NMB Daemon. Mar 12 18:18:13 volumio systemd[1]: Starting Samba Winbind Daemon... Mar 12 18:18:13 volumio ntpd[771]: Listen normally on 3 eth0 10.0.0.231:123 Mar 12 18:18:13 volumio ntpd[771]: new interface(s) found: waking up resolver Mar 12 18:18:13 volumio wireless.js[601]: trying... Mar 12 18:18:13 volumio winbindd[1038]: [2025/03/12 18:18:13.671929, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Mar 12 18:18:13 volumio winbindd[1038]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 12 18:18:13 volumio sudo[1041]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 18:18:13 volumio sudo[1041]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:13 volumio sudo[1041]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:13 volumio winbindd[1038]: [2025/03/12 18:18:13.798543, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 12 18:18:13 volumio winbindd[1038]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Mar 12 18:18:13 volumio systemd[1]: Started Samba Winbind Daemon. Mar 12 18:18:13 volumio systemd[1]: Starting Samba SMB Daemon... Mar 12 18:18:14 volumio wireless.js[601]: trying... Mar 12 18:18:14 volumio sudo[1048]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 18:18:14 volumio sudo[1048]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:14 volumio sudo[1048]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:14 volumio smbd[1046]: [2025/03/12 18:18:14.972305, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 12 18:18:14 volumio systemd[1]: Started Samba SMB Daemon. Mar 12 18:18:14 volumio smbd[1046]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Mar 12 18:18:15 volumio wireless.js[601]: trying... Mar 12 18:18:15 volumio sudo[1058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 18:18:15 volumio sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:15 volumio sudo[1058]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:16 volumio systemd[1]: apt-daily.service: Succeeded. Mar 12 18:18:16 volumio systemd[1]: Started Daily apt download activities. Mar 12 18:18:16 volumio wireless.js[601]: trying... Mar 12 18:18:16 volumio sudo[1090]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 18:18:16 volumio sudo[1090]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:16 volumio sudo[1090]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:17 volumio shairport-sync[729]: no RTSP header received Mar 12 18:18:17 volumio shairport-sync[729]: no RTSP header received Mar 12 18:18:17 volumio volumio-remote-updater[618]: [2025-03-12 18:18:17] [info] asio async_connect error: system:111 (Connection refused) Mar 12 18:18:17 volumio volumio-remote-updater[618]: [2025-03-12 18:18:17] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Mar 12 18:18:17 volumio volumio-remote-updater[618]: [2025-03-12 18:18:17] [error] handle_connect error: Underlying Transport Error Mar 12 18:18:17 volumio dhcpcd[997]: wlan0: leased 10.0.0.244 for 86400 seconds Mar 12 18:18:17 volumio avahi-daemon[625]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.0.0.244. Mar 12 18:18:17 volumio avahi-daemon[625]: New relevant interface wlan0.IPv4 for mDNS. Mar 12 18:18:17 volumio avahi-daemon[625]: Registering new address record for 10.0.0.244 on wlan0.IPv4. Mar 12 18:18:17 volumio dhcpcd[997]: wlan0: adding route to 10.0.0.0/24 Mar 12 18:18:17 volumio dhcpcd[997]: wlan0: adding default route via 10.0.0.1 Mar 12 18:18:17 volumio wireless.js[601]: trying... Mar 12 18:18:17 volumio sudo[1115]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 18:18:17 volumio sudo[1115]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:17 volumio sudo[1115]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:17 volumio wireless.js[601]: Connected to: ----Martin Router King Mar 12 18:18:17 volumio wireless.js[601]: ---- Mar 12 18:18:17 volumio sudo[1118]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 12 18:18:17 volumio sudo[1118]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:17 volumio sudo[1118]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:17 volumio wireless.js[601]: ... joined AP, wlan0 IPv4 is 10.0.0.244, ipV6 is undefined Mar 12 18:18:17 volumio wireless.js[601]: It's done! AP Mar 12 18:18:17 volumio systemd[1]: Started Wireless Services. Mar 12 18:18:17 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 12 18:18:17 volumio systemd[1]: Started Volumio Backend Module. Mar 12 18:18:17 volumio systemd[1]: Started Volumio Cpu Tweaker. Mar 12 18:18:17 volumio systemd[1]: Reached target Multi-User System. Mar 12 18:18:17 volumio systemd[1]: Reached target Graphical Interface. Mar 12 18:18:17 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 12 18:18:17 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 12 18:18:17 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 12 18:18:17 volumio volumio-cpu-tweak[1124]: Setting RT Priority for mpd Mar 12 18:18:17 volumio volumio-cpu-tweak[1124]: Setting MPD Affinity Mar 12 18:18:17 volumio volumio-cpu-tweak[1124]: pid 819's current affinity mask: f Mar 12 18:18:17 volumio volumio-cpu-tweak[1124]: pid 819's new affinity mask: 3 Mar 12 18:18:17 volumio volumio-cpu-tweak[1124]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Mar 12 18:18:17 volumio volumio-cpu-tweak[1124]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Mar 12 18:18:17 volumio systemd[1]: Startup finished in 14.284s (kernel) + 20.696s (userspace) = 34.980s. Mar 12 18:18:17 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Mar 12 18:18:18 volumio ntpd[771]: Listen normally on 4 wlan0 10.0.0.244:123 Mar 12 18:18:18 volumio ntpd[771]: new interface(s) found: waking up resolver Mar 12 18:18:20 volumio volumio[1123]: info: ------------------------------------------- Mar 12 18:18:20 volumio volumio[1123]: info: ----- Volumio3 ---- Mar 12 18:18:20 volumio volumio[1123]: info: ------------------------------------------- Mar 12 18:18:20 volumio volumio[1123]: info: ----- System startup ---- Mar 12 18:18:20 volumio volumio[1123]: info: ------------------------------------------- Mar 12 18:18:21 volumio volumio[1123]: info: MYVOLUMIO Environment detected Mar 12 18:18:22 volumio volumio[1123]: info: Plugin folders cleanup Mar 12 18:18:22 volumio volumio[1123]: info: Scanning into folder /volumio/app/plugins/ Mar 12 18:18:22 volumio volumio[1123]: info: Scanning category audio_interface Mar 12 18:18:22 volumio volumio[1123]: info: Scanning category miscellanea Mar 12 18:18:22 volumio volumio[1123]: info: Scanning category music_service Mar 12 18:18:22 volumio volumio[1123]: info: Scanning category plugins.json Mar 12 18:18:22 volumio volumio[1123]: info: Scanning category system_controller Mar 12 18:18:22 volumio volumio[1123]: info: Scanning category user_interface Mar 12 18:18:22 volumio volumio[1123]: info: Scanning into folder /data/plugins/ Mar 12 18:18:22 volumio volumio[1123]: info: Scanning category audio_interface Mar 12 18:18:22 volumio volumio[1123]: info: Scanning category music_service Mar 12 18:18:22 volumio volumio[1123]: info: Plugin folders cleanup completed Mar 12 18:18:22 volumio volumio[1123]: info: ------------------------------------------- Mar 12 18:18:22 volumio volumio[1123]: info: ----- Core plugins startup ---- Mar 12 18:18:22 volumio volumio[1123]: info: ------------------------------------------- Mar 12 18:18:22 volumio volumio[1123]: info: Loading plugins from folder /volumio/app/plugins/ Mar 12 18:18:22 volumio volumio[1123]: info: Adding plugin upnp to MyMusic Plugins Mar 12 18:18:22 volumio volumio[1123]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 12 18:18:22 volumio volumio[1123]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 12 18:18:22 volumio volumio[1123]: info: Loading plugins from folder /data/plugins/ Mar 12 18:18:22 volumio volumio[1123]: info: Loading plugin "system"... Mar 12 18:18:22 volumio volumio[1123]: info: Loading plugin "appearance"... Mar 12 18:18:23 volumio volumio[1123]: info: Loading plugin "network"... Mar 12 18:18:23 volumio volumio[1123]: info: Refreshing Cached IP Addresses Mar 12 18:18:23 volumio sudo[1155]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 12 18:18:23 volumio sudo[1155]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:23 volumio sudo[1155]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:23 volumio sudo[1157]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 12 18:18:23 volumio sudo[1157]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:24 volumio volumio[1123]: info: Loading plugin "services"... Mar 12 18:18:24 volumio sudo[1157]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:24 volumio volumio[1123]: info: Loading plugin "alsa_controller"... Mar 12 18:18:24 volumio sudo[1166]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 12 18:18:24 volumio sudo[1166]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:24 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 12 18:18:24 volumio volumio[1123]: info: Loading plugin "wizard"... Mar 12 18:18:24 volumio volumio[1123]: info: Loading plugin "networkfs"... Mar 12 18:18:24 volumio volumio[1123]: info: Starting Udev Watcher for removable devices Mar 12 18:18:24 volumio sudo[1183]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Mika,password=a7Bko19c!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //10.0.0.3/Musik /mnt/NAS/Musik Mar 12 18:18:24 volumio sudo[1183]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:24 volumio volumio[1123]: info: Ignoring mount for partition: boot Mar 12 18:18:24 volumio volumio[1123]: info: Ignoring mount for partition: volumio Mar 12 18:18:24 volumio volumio[1123]: info: Ignoring mount for partition: volumio_data Mar 12 18:18:24 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 12 18:18:24 volumio volumio[1123]: info: Loading plugin "volumio_command_line_client"... Mar 12 18:18:24 volumio volumio[1123]: info: Loading plugin "upnp"... Mar 12 18:18:24 volumio volumio[1123]: info: [1741799904312] Starting Upmpd Daemon Mar 12 18:18:24 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 12 18:18:24 volumio volumio[1123]: info: Loading plugin "my_music"... Mar 12 18:18:24 volumio volumio[1123]: info: Loading plugin "mpd"... Mar 12 18:18:24 volumio kernel: Key type cifs.spnego registered Mar 12 18:18:24 volumio kernel: Key type cifs.idmap registered Mar 12 18:18:24 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Mar 12 18:18:24 volumio kernel: CIFS: Attempting to mount //10.0.0.3/Musik Mar 12 18:18:24 volumio kernel: cryptd: max_cpu_qlen set to 1000 Mar 12 18:18:24 volumio sudo[1183]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:24 volumio sudo[1166]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:25 volumio volumio[1123]: info: Loading plugin "upnp_browser"... Mar 12 18:18:25 volumio volumio[1123]: info: Loading plugin "alarm-clock"... Mar 12 18:18:25 volumio volumio[1123]: info: Loading plugin "airplay_emulation"... Mar 12 18:18:25 volumio volumio[1123]: info: Starting Shairport Sync Mar 12 18:18:25 volumio volumio[1123]: info: Loading plugin "last_100"... Mar 12 18:18:25 volumio volumio[1123]: info: Loading plugin "webradio"... Mar 12 18:18:25 volumio volumio[1123]: info: Loading plugin "i2s_dacs"... Mar 12 18:18:25 volumio volumio[1123]: info: Loading plugin "volumiodiscovery"... Mar 12 18:18:26 volumio volumio[1123]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 12 18:18:26 volumio volumio[1123]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 12 18:18:26 volumio volumio[1123]: *** WARNING *** For more information see Mar 12 18:18:26 volumio volumio[1123]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 12 18:18:26 volumio volumio[1123]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 12 18:18:26 volumio volumio[1123]: *** WARNING *** For more information see Mar 12 18:18:26 volumio node[1123]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 12 18:18:26 volumio node[1123]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 12 18:18:26 volumio node[1123]: *** WARNING *** For more information see Mar 12 18:18:26 volumio node[1123]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 12 18:18:26 volumio node[1123]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 12 18:18:26 volumio node[1123]: *** WARNING *** For more information see Mar 12 18:18:26 volumio volumio[1123]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 12 18:18:26 volumio volumio[1123]: info: Discovery: Started advertising with name: Volumio Mar 12 18:18:26 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 12 18:18:26 volumio volumio[1123]: info: Loading plugin "spop"... Mar 12 18:18:27 volumio volumio-remote-updater[618]: [2025-03-12 18:18:27] [connect] Successful connection Mar 12 18:18:28 volumio volumio[1123]: info: Loading plugin "outputs"... Mar 12 18:18:28 volumio volumio[1123]: info: Loading plugin "albumart"... Mar 12 18:18:28 volumio volumio[1123]: info: Plugin example_plugin is not enabled Mar 12 18:18:28 volumio volumio[1123]: info: Loading plugin "inputs"... Mar 12 18:18:28 volumio volumio[1123]: info: Loading plugin "updater_comm"... Mar 12 18:18:28 volumio volumio[1123]: info: Plugin mpdemulation is not enabled Mar 12 18:18:28 volumio volumio[1123]: info: Loading plugin "rest_api"... Mar 12 18:18:28 volumio volumio[1123]: info: Loading plugin "websocket"... Mar 12 18:18:28 volumio volumio[1123]: info: Starting Socket.io Server version 2.3.0 Mar 12 18:18:28 volumio volumio[1123]: info: Loading plugin "fusiondsp"... Mar 12 18:18:28 volumio volumio[1123]: Forking 3 albumart workers Mar 12 18:18:29 volumio shairport-sync[729]: no RTSP header received Mar 12 18:18:29 volumio volumio[1123]: info: Applying required configuration parameters for plugin fusiondsp Mar 12 18:18:29 volumio volumio[1123]: info: Loading i18n strings for locale de Mar 12 18:18:29 volumio volumio[1123]: Updating browse sources language Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 18:18:29 volumio volumio[1123]: Starting albumart workers Mar 12 18:18:29 volumio volumio[1123]: Starting albumart workers Mar 12 18:18:29 volumio volumio[1123]: Starting albumart workers Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::initPlayerControls Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 12 18:18:29 volumio volumio[1123]: Express server listening on port 3000 Mar 12 18:18:29 volumio volumio[1123]: [Metrics] WebUI: 10s 166.57ms Mar 12 18:18:29 volumio volumio[1123]: info: CoreStateMachine::resetVolumioState Mar 12 18:18:29 volumio volumio[1123]: info: CoreStateMachine::getcurrentVolume Mar 12 18:18:29 volumio volumio[1123]: info: CoreCommandRouter::volumioRetrievevolume Mar 12 18:18:30 volumio volumio[1123]: info: Volumio Network Manager: Network status updated: 3 Mar 12 18:18:30 volumio volumio-remote-updater[618]: [2025-03-12 18:18:30] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1741799907 101 Mar 12 18:18:30 volumio volumio[1123]: 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 Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 12 18:18:30 volumio volumio[1123]: info: Reloading queue from file Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:30 volumio volumio[1123]: info: VolumeController:: Volume=33 Mute =false Mar 12 18:18:30 volumio volumio[1123]: info: CoreStateMachine::pushState Mar 12 18:18:30 volumio volumio[1123]: info: CorePlayQueue::getTrack 0 Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::volumioPushState Mar 12 18:18:30 volumio volumio[1123]: info: CoreStateMachine::updateTrackBlock Mar 12 18:18:30 volumio volumio[1123]: info: CorePlayQueue::getTrackBlock Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::volumioRetrievevolume Mar 12 18:18:30 volumio volumio[1123]: info: CoreStateMachine::setRepeat null single undefined Mar 12 18:18:30 volumio volumio[1123]: info: CoreStateMachine::pushState Mar 12 18:18:30 volumio volumio[1123]: info: CorePlayQueue::getTrack 0 Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::volumioPushState Mar 12 18:18:30 volumio volumio[1123]: info: CoreStateMachine::setRandom null Mar 12 18:18:30 volumio volumio[1123]: info: CoreStateMachine::pushState Mar 12 18:18:30 volumio volumio[1123]: info: CorePlayQueue::getTrack 0 Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::volumioPushState Mar 12 18:18:30 volumio volumio[1123]: info: Setting Device type: Raspberry PI Mar 12 18:18:30 volumio volumio[1123]: info: Completed loading Core Plugins Mar 12 18:18:30 volumio volumio[1123]: info: Preparing to generate the ALSA configuration file Mar 12 18:18:30 volumio volumio[1123]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 12 18:18:30 volumio volumio[1123]: info: Reading ALSA contributions from plugins. Mar 12 18:18:30 volumio volumio[1123]: info: Asound.conf file unchanged, so no further update is needed Mar 12 18:18:30 volumio volumio[1123]: info: Output device has changed, restarting MPD Mar 12 18:18:30 volumio volumio[1123]: info: Output device has changed, restarting Shairport Sync Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:30 volumio sudo[1290]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 12 18:18:30 volumio sudo[1290]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:30 volumio sudo[1290]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:30 volumio sudo[1292]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 12 18:18:30 volumio sudo[1292]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:30 volumio systemd[1]: Stopping Music Player Daemon... Mar 12 18:18:30 volumio volumio[1123]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 12 18:18:30 volumio volumio[1123]: info: ___________ START PLUGINS ___________ Mar 12 18:18:30 volumio volumio[1123]: info: ControllerMpd::onStart: Initializing MPD Mar 12 18:18:30 volumio volumio[1123]: info: Creating MPD Configuration file Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 12 18:18:30 volumio volumio[1123]: info: [1741799910870] CoreMusicLibrary::Adding element Medienserver Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 18:18:30 volumio sudo[1299]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 12 18:18:30 volumio sudo[1299]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:30 volumio sudo[1299]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:30 volumio sudo[1301]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 12 18:18:30 volumio sudo[1301]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:30 volumio volumio[1123]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:30 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 12 18:18:31 volumio volumio[1123]: info: [1741799911004] CoreMusicLibrary::Adding element Last_100 Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 12 18:18:31 volumio volumio[1123]: info: [1741799911008] CoreMusicLibrary::Adding element Webradio Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 12 18:18:31 volumio volumio[1123]: info: Initializing BBC Radios Mar 12 18:18:31 volumio systemd[1]: mpd.service: Succeeded. Mar 12 18:18:31 volumio systemd[1]: Stopped Music Player Daemon. Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: Creating Spotify config file Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio systemd[1]: Starting Music Player Daemon... Mar 12 18:18:31 volumio volumio[1123]: info: Loading i18n strings for locale de Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: FusionDsp - mixtype--------------------- Hardware Mar 12 18:18:31 volumio volumio[1123]: info: Volumio Calling Home Mar 12 18:18:31 volumio sudo[1313]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 12 18:18:31 volumio sudo[1313]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:31 volumio volumio[1123]: info: Preparing to generate the ALSA configuration file Mar 12 18:18:31 volumio sudo[1313]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:31 volumio volumio[1123]: info: Discovery: adding cda06f7d-836a-4f69-b5d9-df30ae294586 Mar 12 18:18:31 volumio volumio[1123]: info: Discovery: Found device Volumio Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::volumioGetState Mar 12 18:18:31 volumio volumio[1123]: info: CorePlayQueue::getTrack 0 Mar 12 18:18:31 volumio volumio[1123]: info: Discovery: this is already registered, cda06f7d-836a-4f69-b5d9-df30ae294586 Mar 12 18:18:31 volumio volumio[1123]: info: Discovery: Found device Volumio Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::volumioGetState Mar 12 18:18:31 volumio volumio[1123]: info: CorePlayQueue::getTrack 0 Mar 12 18:18:31 volumio volumio[1123]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 12 18:18:31 volumio volumio[1123]: info: Reading ALSA contributions from plugins. Mar 12 18:18:31 volumio volumio[1123]: info: MPD Permissions set Mar 12 18:18:31 volumio volumio[1123]: info: MPD Permissions set Mar 12 18:18:31 volumio volumio[1123]: info: VolumeController:: Volume=33 Mute =false Mar 12 18:18:31 volumio volumio[1123]: info: CoreStateMachine::pushState Mar 12 18:18:31 volumio volumio[1123]: info: CorePlayQueue::getTrack 0 Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::volumioPushState Mar 12 18:18:31 volumio volumio[1123]: info: Volumio called home Mar 12 18:18:31 volumio volumio[1123]: info: Spotify config file written Mar 12 18:18:31 volumio sudo[1327]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 12 18:18:31 volumio systemd[1]: systemd-fsckd.service: Succeeded. Mar 12 18:18:31 volumio sudo[1327]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:31 volumio volumio[1123]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:31 volumio volumio[1123]: info: No need to fix Spotify hosts Mar 12 18:18:31 volumio systemd[1]: Started go-librespot Daemon. Mar 12 18:18:31 volumio go-librespot[1335]: go-librespot daemon starting... Mar 12 18:18:31 volumio sudo[1327]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:31 volumio volumio[1123]: info: Starting Shairport Sync Mar 12 18:18:32 volumio volumio[1123]: info: Starting Shairport Sync Mar 12 18:18:32 volumio volumio[1123]: info: Starting Shairport Sync Mar 12 18:18:32 volumio sudo[1347]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 12 18:18:32 volumio sudo[1347]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:32 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 12 18:18:32 volumio systemd[1]: shairport-sync.service: Succeeded. Mar 12 18:18:32 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 12 18:18:32 volumio volumio[1123]: info: CoreCommandRouter::volumioGetState Mar 12 18:18:32 volumio sudo[1352]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 12 18:18:32 volumio sudo[1349]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 12 18:18:32 volumio volumio[1123]: info: CorePlayQueue::getTrack 0 Mar 12 18:18:32 volumio sudo[1352]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:32 volumio sudo[1349]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:32 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 12 18:18:32 volumio sudo[1347]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:32 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 12 18:18:32 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Mar 12 18:18:32 volumio systemd[1]: shairport-sync.service: Succeeded. Mar 12 18:18:32 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 12 18:18:32 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 12 18:18:32 volumio sudo[1349]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:32 volumio sudo[1352]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:32 volumio volumio[1123]: info: Asound.conf file unchanged, so no further update is needed Mar 12 18:18:32 volumio volumio[1123]: info: Output device has changed, restarting MPD Mar 12 18:18:32 volumio volumio[1123]: info: Output device has changed, restarting Shairport Sync Mar 12 18:18:32 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:32 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:32 volumio sudo[1360]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 12 18:18:32 volumio shairport-sync[1356]: no RTSP header received Mar 12 18:18:32 volumio sudo[1360]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:32 volumio sudo[1360]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:32 volumio sudo[1362]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 12 18:18:32 volumio sudo[1362]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:32 volumio volumio[1123]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 12 18:18:32 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Mar 12 18:18:32 volumio systemd[1]: mpd.service: Succeeded. Mar 12 18:18:32 volumio systemd[1]: Stopped Music Player Daemon. Mar 12 18:18:32 volumio volumio[1123]: info: Shairport-Sync Started Mar 12 18:18:32 volumio volumio[1123]: Error adding Membership: Error: addMembership EINVAL Mar 12 18:18:32 volumio volumio[1123]: info: Shairport-Sync Started Mar 12 18:18:32 volumio volumio[1123]: info: Shairport-Sync Started Mar 12 18:18:32 volumio volumio[1123]: info: MPD Permissions set Mar 12 18:18:32 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:32 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:32 volumio systemd[1]: Starting Music Player Daemon... Mar 12 18:18:32 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:32 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 18:18:32 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:32 volumio volumio[1123]: info: Starting Shairport Sync Mar 12 18:18:32 volumio sudo[1376]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 12 18:18:32 volumio sudo[1376]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:32 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 12 18:18:32 volumio systemd[1]: shairport-sync.service: Succeeded. Mar 12 18:18:32 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 12 18:18:32 volumio sudo[1369]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 12 18:18:32 volumio sudo[1369]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:32 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 12 18:18:32 volumio sudo[1369]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:32 volumio sudo[1376]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:32 volumio volumio[1123]: info: Shairport-Sync Started Mar 12 18:18:32 volumio go-librespot[1335]: time="2025-03-12T18:18:32+01:00" level=info msg="running go-librespot 0.2.0" Mar 12 18:18:32 volumio go-librespot[1335]: time="2025-03-12T18:18:32+01:00" level=debug msg="app state loaded" Mar 12 18:18:32 volumio go-librespot[1335]: time="2025-03-12T18:18:32+01:00" level=debug msg="stored credentials not found" Mar 12 18:18:32 volumio go-librespot[1335]: time="2025-03-12T18:18:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 12 18:18:33 volumio go-librespot[1335]: time="2025-03-12T18:18:33+01: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]" Mar 12 18:18:33 volumio go-librespot[1335]: time="2025-03-12T18:18:33+01: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]" Mar 12 18:18:33 volumio go-librespot[1335]: time="2025-03-12T18:18:33+01: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]" Mar 12 18:18:33 volumio go-librespot[1335]: time="2025-03-12T18:18:33+01:00" level=info msg="zeroconf server listening on port 45155" Mar 12 18:18:33 volumio shairport-sync[1380]: no RTSP header received Mar 12 18:18:33 volumio shairport-sync[1380]: no RTSP header received Mar 12 18:18:33 volumio shairport-sync[1380]: no RTSP header received Mar 12 18:18:33 volumio volumio[1123]: info: camilladsp spawned new process with pid 1395, instance 1, run: true Mar 12 18:18:33 volumio volumio[1123]: info: camilladsp service started and running in background, instance 1 Mar 12 18:18:33 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp - AAAAAAAAAAAAAA-> 22050 44100 48000 88200 96000 176400 192000 384000 <-AAAAAAAAAAAAA Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp loaded Mar 12 18:18:33 volumio volumio[1123]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 12 18:18:33 volumio sudo[1399]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Mar 12 18:18:33 volumio sudo[1399]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp - Reporting Fusion DSP Enabled Mar 12 18:18:33 volumio volumio[1123]: info: Adding Signal Path Element [object Object] Mar 12 18:18:33 volumio volumio[1123]: info: Adding fusiondspeq DSP Signal Path Element Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp - ---- installed callbackRead Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp - Loudness is ON true Mar 12 18:18:33 volumio volumio[1123]: info: CoreCommandRouter::volumioGetState Mar 12 18:18:33 volumio volumio[1123]: info: CorePlayQueue::getTrack 0 Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp - volume level for loudness 33 gain applied 8.69 Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 12 18:18:33 volumio volumio[1123]: info: FusionDsp - Loudness is ON true Mar 12 18:18:33 volumio volumio[1123]: error: FusionDsp - WebSocket error: [object Object] Mar 12 18:18:33 volumio volumio[1123]: error: FusionDsp - WebSocket error: [object Object] Mar 12 18:18:33 volumio volumio[1123]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 12 18:18:33 volumio systemd[1]: Started FusionDsp Daemon. Mar 12 18:18:33 volumio sudo[1399]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:34 volumio mpd[1381]: Mar 12 18:18 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 12 18:18:34 volumio systemd[1]: Started Music Player Daemon. Mar 12 18:18:34 volumio sudo[1362]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:34 volumio sudo[1292]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:34 volumio sudo[1301]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:34 volumio volumio[1123]: info: Completed starting Core Plugins Mar 12 18:18:34 volumio volumio[1123]: info: ------------------------------------------- Mar 12 18:18:34 volumio volumio[1123]: info: ----- MyVolumio plugins startup ---- Mar 12 18:18:34 volumio volumio[1123]: info: ------------------------------------------- Mar 12 18:18:34 volumio volumio[1123]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 12 18:18:34 volumio volumio[1123]: error: MPD error: The expression evaluated to a falsy value: Mar 12 18:18:34 volumio volumio[1123]: assert.ok(self.idling) Mar 12 18:18:34 volumio volumio[1123]: error: The expression evaluated to a falsy value: Mar 12 18:18:34 volumio volumio[1123]: assert.ok(self.idling) Mar 12 18:18:34 volumio volumio[1123]: error: MPD error: The expression evaluated to a falsy value: Mar 12 18:18:34 volumio volumio[1123]: assert.ok(self.idling) Mar 12 18:18:34 volumio volumio[1123]: error: The expression evaluated to a falsy value: Mar 12 18:18:34 volumio volumio[1123]: assert.ok(self.idling) Mar 12 18:18:34 volumio sudo[1428]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 12 18:18:34 volumio sudo[1428]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:34 volumio sudo[1430]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 12 18:18:34 volumio volumio[1123]: info: MPD running with PID1381 Mar 12 18:18:34 volumio volumio[1123]: ,establishing connection Mar 12 18:18:34 volumio sudo[1430]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:34 volumio sudo[1428]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:34 volumio volumio[1123]: error: updateQueue error: null Mar 12 18:18:34 volumio sudo[1430]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:34 volumio volumio[1123]: error: updateQueue error: null Mar 12 18:18:34 volumio sudo[1434]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 12 18:18:34 volumio sudo[1434]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 18:18:34 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Mar 12 18:18:34 volumio sudo[1434]: pam_unix(sudo:session): session closed for user root Mar 12 18:18:34 volumio volumio[1123]: info: Upmpdcli Daemon Started Mar 12 18:18:34 volumio volumio[1436]: Generating RSA private key, 4096 bit long modulus (2 primes) Mar 12 18:18:34 volumio volumio[1123]: info: go-librespot daemon successfully initialized Mar 12 18:18:34 volumio go-librespot[1335]: time="2025-03-12T18:18:34+01:00" level=debug msg="obtained new client token: AAApyFOT1qpH2MrAYcnStaPydpE+MV4eILV6jVi6c6bc7tZl+JpFzFNm+qN+4KjM25EVSzt8QI7KaeWHNlctGfbGqAqLVNwwD+qDnj8fkpFZ7bt4YkdQ+3Rz/KiR5ybsyXdbnQIMMDwn3Z+s5h51PIq9cUr/bhxDq0RvLyz0Q8Bz7YLrHzdFxf5Ce+k57+U9j1FQH1yoUkJjH//WhWsGSCJqYiO03iaz5RJFq4TLOCn3uQWHJw9/SRB4s3lq" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="completed keyexchange" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="completed challenge" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=info msg="authenticated AP as macmika28" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=info msg="authenticated Login5 as macmika28" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=info msg="accepted zeroconf user macmika28 from Z Fold6 von Michael" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="dealer connection opened" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=trace msg="starting accesspoint recv loop" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=trace msg="starting dealer recv loop" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=trace msg="received accesspoint ping" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="received connection id: OWQ0ZTU4N2MtN2EyOS00MDdmLWEzNDctMDdlMTU5N2MwMTZmK2RlYWxlcit0Y3A6Ly8wYWNhNThiZC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNkYwMTg2QkE1OEY1QTE1NjA4RDAzN0UxQzNFMzFEMERDNzkyMUQyNjc0OUJGRTgxMzQ2NzcwM0ZCN0Q3NUNGQQ==" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=trace msg="received accesspoint pong ack" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="handling transfer player command from baf68b91cdc037c8a392793e8b599931845c411b" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWTvNyxOwkztu" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=trace msg="fetched new page 0 with 78 items (list: 78)" uri="spotify:playlist:37i9dQZF1DWTvNyxOwkztu" Mar 12 18:18:35 volumio go-librespot[1335]: time="2025-03-12T18:18:35+01:00" level=debug msg="loading track (paused: true, position: 136880ms)" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=trace msg="emitting websocket event: will_play" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1271" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="selected format OGG_VORBIS_320 (73737b8f602b091f1648df88fc07fc7f883797e8)" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="requested aes key for file 73737b8f602b091f1648df88fc07fc7f883797e8, gid: 715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="fetched first chunk of 10, total size is 4954460 bytes" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="fetched chunk 1/9, size: 524288" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="fetched chunk 3/9, size: 524288" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="fetched chunk 9/9, size: 235868" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=trace msg="seek to 136880ms (diff: 5062ms, samples: 6036408, bytes: 4937574)" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="created new output device" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=info msg="loaded track \"Heaven\" (paused: true, position: 136880ms, duration: 136880ms, prefetched: false)" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="fetched chunk 2/9, size: 524288" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=trace msg="emitting websocket event: metadata" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=trace msg="emitting websocket event: active" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="sending successful reply for dealer request" Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 12 18:18:36 volumio go-librespot[1335]: time="2025-03-12T18:18:36+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="emitting websocket event: paused" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="handling resume player command from baf68b91cdc037c8a392793e8b599931845c411b" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="seek to 136880ms (diff: 5062ms, samples: 6036408, bytes: 4937574)" uri="spotify:track:715a5BoI21BDN8GNbrJJ8G" Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - ---- read samplerate from file: 44100 Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Mar 12 18:18:37 volumio volumio[1123]: info: camilladsp stopping service pid 1395... Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="resume track at 131694ms" Mar 12 18:18:37 volumio volumio[1123]: info: camilladsp service terminated, instance 1 Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - Loudness is ON true Mar 12 18:18:37 volumio volumio[1123]: info: camilladsp service started and running in background, instance 1 Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - ---- read samplerate from file: 44100 Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - Loudness is ON true Mar 12 18:18:37 volumio volumio[1123]: error: FusionDsp - WebSocket error: [object Object] Mar 12 18:18:37 volumio volumio[1123]: info: camilladsp spawned new process with pid 1458, instance 1, run: true Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="sending successful reply for dealer request" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=warning msg="cannot prefetch next track because the uri field is empty" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="emitting websocket event: playing" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="emitting websocket event: not_playing" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="emitting websocket event: will_play" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="selected format OGG_VORBIS_320 (88938f73ef8c923dfabfbfb8eecc5b1dac0d4925)" uri="spotify:track:75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="requested aes key for file 88938f73ef8c923dfabfbfb8eecc5b1dac0d4925, gid: 75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="fetched first chunk of 12, total size is 5884680 bytes" uri="spotify:track:75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - ---- read samplerate, raw: Mar 12 18:18:37 volumio volumio[1123]: error: FusionDsp - invalid sample rate Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=info msg="loaded track \"As Long As You Love Me\" (paused: false, position: 1ms, duration: 158368ms, prefetched: false)" uri="spotify:track:75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - ---- read samplerate from file: 44100 Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - Loudness is ON true Mar 12 18:18:37 volumio volumio[1123]: info: FusionDsp - {"Reload":{"result":"Ok"}} Mar 12 18:18:37 volumio volumio[1123]: info: Initializing connection to go-librespot Websocket Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="new websocket client" Mar 12 18:18:37 volumio volumio[1123]: info: Connection to go-librespot Websocket established Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="scheduling prefetch in 128s" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="emitting websocket event: metadata" Mar 12 18:18:37 volumio volumio[1123]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:75nLmZ3IjorDYevGhuhahs","name":"As Long As You Love Me","artist_names":["Lilly Bay"],"album_name":"As Long As You Love Me","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0280f5981c32d9a4a4abaab166","position":1,"duration":158368,"release_date":"year:2022 month:12 day:30","track_number":1,"disc_number":1}} Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:75nLmZ3IjorDYevGhuhahs" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 18:18:37 volumio go-librespot[1335]: time="2025-03-12T18:18:37+01:00" level=trace msg="emitting websocket event: playing" Mar 12 18:18:37 volumio volumio[1123]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:75nLmZ3IjorDYevGhuhahs","play_origin":"com.spotify.gaia"}} Mar 12 18:18:37 volumio volumio[1123]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 12 18:18:37 volumio volumio[1123]: TypeError: Cannot read property 'service' of undefined Mar 12 18:18:37 volumio volumio[1123]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Mar 12 18:18:37 volumio volumio[1123]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Mar 12 18:18:37 volumio volumio[1123]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Mar 12 18:18:37 volumio volumio[1123]: at WebSocket.emit (events.js:315:20) Mar 12 18:18:37 volumio volumio[1123]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 12 18:18:37 volumio volumio[1123]: at Receiver.emit (events.js:315:20) Mar 12 18:18:37 volumio volumio[1123]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 12 18:18:37 volumio volumio[1123]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 12 18:18:37 volumio volumio[1123]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 12 18:18:37 volumio volumio[1123]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 12 18:18:37 volumio volumio[1123]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 12 18:18:37 volumio volumio[1123]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 12 18:18:37 volumio volumio[1123]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 12 18:18:37 volumio volumio[1123]: at Socket.emit (events.js:315:20) Mar 12 18:18:37 volumio volumio[1123]: at addChunk (internal/streams/readable.js:309:12) Mar 12 18:18:37 volumio volumio[1123]: at readableAddChunk (internal/streams/readable.js:284:9) Mar 12 18:18:38 volumio volumio[1123]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 12 18:18:38 volumio sudo[1476]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-12 18:17 Mar 12 18:18:38 volumio sudo[1476]: 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"