-- Logs begin at Thu 2019-02-14 05:11:58 EST, end at Wed 2025-03-12 14:55:00 EDT. -- Mar 12 14:54:00 volumio-attic wireless.js[667]: trying... Mar 12 14:54:00 volumio-attic sudo[984]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:00 volumio-attic sudo[984]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:00 volumio-attic sudo[984]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:01 volumio-attic wireless.js[667]: trying... Mar 12 14:54:01 volumio-attic sudo[987]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:01 volumio-attic sudo[987]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:01 volumio-attic sudo[987]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:02 volumio-attic wireless.js[667]: trying... Mar 12 14:54:02 volumio-attic volumio-time-update[678]: volumio-time-update-util: Fetching time from Volumio... Mar 12 14:54:03 volumio-attic volumio-time-update[678]: volumio-time-update-util: Date not found in response Mar 12 14:54:03 volumio-attic volumio-time-update[678]: volumio-time-update-util: Retrying in 5 seconds... Mar 12 14:54:03 volumio-attic kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd022 fail, reason -52 Mar 12 14:54:03 volumio-attic kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd026 fail, reason -52 Mar 12 14:54:03 volumio-attic kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02a fail, reason -52 Mar 12 14:54:03 volumio-attic kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02e fail, reason -52 Mar 12 14:54:06 volumio-attic volumio-remote-updater[679]: [2025-03-12 14:54:06] [info] asio async_connect error: system:111 (Connection refused) Mar 12 14:54:06 volumio-attic volumio-remote-updater[679]: [2025-03-12 14:54:06] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Mar 12 14:54:06 volumio-attic volumio-remote-updater[679]: [2025-03-12 14:54:06] [error] handle_connect error: Underlying Transport Error Mar 12 14:54:06 volumio-attic wpa_supplicant[970]: wlan0: Trying to associate with SSID 'FiOS-F3FXZ' Mar 12 14:54:06 volumio-attic sudo[990]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:06 volumio-attic sudo[990]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:06 volumio-attic sudo[990]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:06 volumio-attic wireless.js[667]: trying... Mar 12 14:54:06 volumio-attic sudo[998]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:06 volumio-attic sudo[998]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:06 volumio-attic sudo[998]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:06 volumio-attic dhcpcd[982]: wlan0: carrier acquired Mar 12 14:54:06 volumio-attic dhcpcd[982]: wlan0: connected to Access Point `FiOS-F3FXZ' Mar 12 14:54:06 volumio-attic wpa_supplicant[970]: wlan0: Associated with 84:16:f9:fc:c2:66 Mar 12 14:54:06 volumio-attic wpa_supplicant[970]: wlan0: CTRL-EVENT-CONNECTED - Connection to 84:16:f9:fc:c2:66 completed [id=0 id_str=] Mar 12 14:54:06 volumio-attic wpa_supplicant[970]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 12 14:54:06 volumio-attic dhcpcd[982]: DUID 00:01:00:01:2d:69:1d:d1:e4:5f:01:ae:37:f3 Mar 12 14:54:06 volumio-attic dhcpcd[982]: wlan0: IAID 01:ae:37:f3 Mar 12 14:54:06 volumio-attic dhcpcd[982]: wlan0: adding address fe80::e521:eef8:40ee:6c02 Mar 12 14:54:06 volumio-attic dhcpcd[982]: ipv6_addaddr1: Permission denied Mar 12 14:54:06 volumio-attic dhcpcd[982]: wlan0: carrier lost Mar 12 14:54:06 volumio-attic dhcpcd[982]: wlan0: carrier acquired Mar 12 14:54:06 volumio-attic dhcpcd[982]: wlan0: IAID 01:ae:37:f3 Mar 12 14:54:06 volumio-attic dhcpcd[982]: wlan0: soliciting an IPv6 router Mar 12 14:54:07 volumio-attic wireless.js[667]: trying... Mar 12 14:54:07 volumio-attic sudo[1013]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:07 volumio-attic sudo[1013]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:07 volumio-attic sudo[1013]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:07 volumio-attic dhcpcd[982]: wlan0: rebinding lease of 192.168.1.65 Mar 12 14:54:07 volumio-attic dhcpcd[982]: wlan0: probing address 192.168.1.65/24 Mar 12 14:54:08 volumio-attic volumio-time-update[678]: volumio-time-update-util: Fetching time from Volumio... Mar 12 14:54:08 volumio-attic volumio-time-update[678]: volumio-time-update-util: Date not found in response Mar 12 14:54:08 volumio-attic volumio-time-update[678]: volumio-time-update-util: Retrying in 5 seconds... Mar 12 14:54:08 volumio-attic wireless.js[667]: trying... Mar 12 14:54:08 volumio-attic sudo[1021]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:08 volumio-attic sudo[1021]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:08 volumio-attic sudo[1021]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:09 volumio-attic wireless.js[667]: trying... Mar 12 14:54:09 volumio-attic sudo[1024]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:09 volumio-attic sudo[1024]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:09 volumio-attic sudo[1024]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:10 volumio-attic wireless.js[667]: trying... Mar 12 14:54:10 volumio-attic sudo[1027]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:10 volumio-attic sudo[1027]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:10 volumio-attic sudo[1027]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:11 volumio-attic wireless.js[667]: trying... Mar 12 14:54:11 volumio-attic sudo[1030]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:11 volumio-attic sudo[1030]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:11 volumio-attic sudo[1030]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:12 volumio-attic wireless.js[667]: trying... Mar 12 14:54:12 volumio-attic sudo[1033]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:12 volumio-attic sudo[1033]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:12 volumio-attic sudo[1033]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:12 volumio-attic dhcpcd[982]: wlan0: leased 192.168.1.65 for 86400 seconds Mar 12 14:54:12 volumio-attic avahi-daemon[675]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.65. Mar 12 14:54:12 volumio-attic dhcpcd[982]: wlan0: adding route to 192.168.1.0/24 Mar 12 14:54:12 volumio-attic avahi-daemon[675]: New relevant interface wlan0.IPv4 for mDNS. Mar 12 14:54:12 volumio-attic dhcpcd[982]: wlan0: adding default route via 192.168.1.1 Mar 12 14:54:12 volumio-attic avahi-daemon[675]: Registering new address record for 192.168.1.65 on wlan0.IPv4. Mar 12 14:54:13 volumio-attic volumio-time-update[678]: volumio-time-update-util: Fetching time from Volumio... Mar 12 14:54:13 volumio-attic wireless.js[667]: trying... Mar 12 14:54:13 volumio-attic sudo[1061]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 12 14:54:13 volumio-attic sudo[1061]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:13 volumio-attic sudo[1061]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:13 volumio-attic wireless.js[667]: Connected to: ----FiOS-F3FXZ Mar 12 14:54:13 volumio-attic wireless.js[667]: ---- Mar 12 14:54:13 volumio-attic sudo[1064]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 12 14:54:13 volumio-attic sudo[1064]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:13 volumio-attic sudo[1064]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:13 volumio-attic wireless.js[667]: ... joined AP, wlan0 IPv4 is 192.168.1.65, ipV6 is undefined Mar 12 14:54:13 volumio-attic wireless.js[667]: It's done! AP Mar 12 14:54:13 volumio-attic volumio-time-update[678]: volumio-time-update-util: Setting system time to: 2025-03-12 14:54:41 Mar 12 14:54:13 volumio-attic sudo[1069]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-03-12 14:54:41 Mar 12 14:54:13 volumio-attic sudo[1069]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:13 volumio-attic kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 12 14:54:13 volumio-attic systemd[1]: Started Wireless Services. Mar 12 14:54:13 volumio-attic systemd[1]: Started Volumio Backend Module. Mar 12 14:54:13 volumio-attic systemd[1]: Started Volumio Cpu Tweaker. Mar 12 14:54:13 volumio-attic dbus-daemon[627]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.9' (uid=0 pid=1070 comm="timedatectl set-time 2025-03-12 14:54:41 ") Mar 12 14:54:13 volumio-attic systemd[1]: Starting Time & Date Service... Mar 12 14:54:13 volumio-attic volumio-cpu-tweak[1073]: Setting RT Priority for mpd Mar 12 14:54:13 volumio-attic volumio-cpu-tweak[1073]: Setting MPD Affinity Mar 12 14:54:13 volumio-attic volumio-cpu-tweak[1073]: pid 837's current affinity mask: f Mar 12 14:54:13 volumio-attic volumio-cpu-tweak[1073]: pid 837's new affinity mask: 3 Mar 12 14:54:13 volumio-attic volumio-cpu-tweak[1073]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Mar 12 14:54:13 volumio-attic volumio-cpu-tweak[1073]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Mar 12 14:54:13 volumio-attic dbus-daemon[627]: [system] Successfully activated service 'org.freedesktop.timedate1' Mar 12 14:54:13 volumio-attic systemd[1]: Started Time & Date Service. Mar 12 14:54:41 volumio-attic systemd-timedated[1084]: Changed local time to Wed Mar 12 14:54:41 2025 Mar 12 14:54:41 volumio-attic sudo[1069]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:41 volumio-attic volumio-time-update[678]: volumio-time-update-util: System time updated successfully. Mar 12 14:54:41 volumio-attic systemd[1]: Started Volumio Time Update Utility. Mar 12 14:54:41 volumio-attic systemd[1]: volumio_cpu_tweak.service: Succeeded. Mar 12 14:54:41 volumio-attic ntpd[822]: Listen normally on 3 wlan0 192.168.1.65:123 Mar 12 14:54:41 volumio-attic ntpd[822]: new interface(s) found: waking up resolver Mar 12 14:54:42 volumio-attic volumio[1072]: info: ------------------------------------------- Mar 12 14:54:42 volumio-attic volumio[1072]: info: ----- Volumio3 ---- Mar 12 14:54:42 volumio-attic volumio[1072]: info: ------------------------------------------- Mar 12 14:54:42 volumio-attic volumio[1072]: info: ----- System startup ---- Mar 12 14:54:42 volumio-attic volumio[1072]: info: ------------------------------------------- Mar 12 14:54:43 volumio-attic volumio[1072]: info: MYVOLUMIO Environment detected Mar 12 14:54:43 volumio-attic volumio[1072]: info: Plugin folders cleanup Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning into folder /volumio/app/plugins/ Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning category audio_interface Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning category miscellanea Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning category music_service Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning category plugins.json Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning category system_controller Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning category user_interface Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning into folder /data/plugins/ Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning category music_service Mar 12 14:54:43 volumio-attic volumio[1072]: info: Scanning category user_interface Mar 12 14:54:43 volumio-attic volumio[1072]: info: Plugin folders cleanup completed Mar 12 14:54:43 volumio-attic volumio[1072]: info: ------------------------------------------- Mar 12 14:54:43 volumio-attic volumio[1072]: info: ----- Core plugins startup ---- Mar 12 14:54:43 volumio-attic volumio[1072]: info: ------------------------------------------- Mar 12 14:54:43 volumio-attic volumio[1072]: info: Loading plugins from folder /volumio/app/plugins/ Mar 12 14:54:43 volumio-attic volumio[1072]: info: Adding plugin upnp to MyMusic Plugins Mar 12 14:54:43 volumio-attic volumio[1072]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 12 14:54:43 volumio-attic volumio[1072]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 12 14:54:43 volumio-attic volumio[1072]: info: Loading plugins from folder /data/plugins/ Mar 12 14:54:43 volumio-attic volumio[1072]: info: Loading plugin "system"... Mar 12 14:54:43 volumio-attic volumio[1072]: info: Loading plugin "appearance"... Mar 12 14:54:43 volumio-attic volumio-remote-updater[679]: [2025-03-12 14:54:43] [connect] Successful connection Mar 12 14:54:43 volumio-attic nmbd[786]: [2025/03/12 14:54:43.699822, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 12 14:54:43 volumio-attic nmbd[786]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Mar 12 14:54:43 volumio-attic systemd[1]: Started Samba NMB Daemon. Mar 12 14:54:43 volumio-attic systemd[1]: Starting Samba Winbind Daemon... Mar 12 14:54:43 volumio-attic winbindd[1103]: [2025/03/12 14:54:43.964365, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Mar 12 14:54:43 volumio-attic winbindd[1103]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 12 14:54:43 volumio-attic winbindd[1103]: [2025/03/12 14:54:43.980621, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 12 14:54:43 volumio-attic systemd[1]: Started Samba Winbind Daemon. Mar 12 14:54:43 volumio-attic winbindd[1103]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Mar 12 14:54:44 volumio-attic systemd[1]: Starting Samba SMB Daemon... Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "network"... Mar 12 14:54:44 volumio-attic volumio[1072]: info: Refreshing Cached IP Addresses Mar 12 14:54:44 volumio-attic smbd[1108]: [2025/03/12 14:54:44.359655, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 12 14:54:44 volumio-attic systemd[1]: Started Samba SMB Daemon. Mar 12 14:54:44 volumio-attic smbd[1108]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Mar 12 14:54:44 volumio-attic systemd[1]: Reached target Multi-User System. Mar 12 14:54:44 volumio-attic systemd[1]: Reached target Graphical Interface. Mar 12 14:54:44 volumio-attic sudo[1115]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 12 14:54:44 volumio-attic sudo[1115]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:44 volumio-attic systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "services"... Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "alsa_controller"... Mar 12 14:54:44 volumio-attic sudo[1115]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:44 volumio-attic sudo[1120]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 12 14:54:44 volumio-attic sudo[1120]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:44 volumio-attic sudo[1120]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:44 volumio-attic sudo[1129]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 12 14:54:44 volumio-attic sudo[1129]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:44 volumio-attic systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 12 14:54:44 volumio-attic systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 12 14:54:44 volumio-attic systemd[1]: Startup finished in 12.646s (kernel) + 27.855s (userspace) = 40.502s. Mar 12 14:54:44 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "wizard"... Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "networkfs"... Mar 12 14:54:44 volumio-attic volumio[1072]: info: Starting Udev Watcher for removable devices Mar 12 14:54:44 volumio-attic sudo[1146]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=rainer,password=nwobhm1,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.211/common/media/mp3 /mnt/NAS/mp3 Mar 12 14:54:44 volumio-attic sudo[1146]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:44 volumio-attic volumio[1072]: info: Ignoring mount for partition: boot Mar 12 14:54:44 volumio-attic volumio[1072]: info: Ignoring mount for partition: volumio Mar 12 14:54:44 volumio-attic volumio[1072]: info: Ignoring mount for partition: volumio_data Mar 12 14:54:44 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "volumio_command_line_client"... Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "upnp"... Mar 12 14:54:44 volumio-attic volumio[1072]: info: [1741805684599] Starting Upmpd Daemon Mar 12 14:54:44 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "my_music"... Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "mpd"... Mar 12 14:54:44 volumio-attic kernel: Key type cifs.spnego registered Mar 12 14:54:44 volumio-attic kernel: Key type cifs.idmap registered Mar 12 14:54:44 volumio-attic 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 14:54:44 volumio-attic kernel: CIFS: Attempting to mount //192.168.1.211/common/media/mp3 Mar 12 14:54:44 volumio-attic volumio[1072]: info: Loading plugin "upnp_browser"... Mar 12 14:54:45 volumio-attic kernel: cryptd: max_cpu_qlen set to 1000 Mar 12 14:54:45 volumio-attic volumio[1072]: info: Loading plugin "alarm-clock"... Mar 12 14:54:45 volumio-attic volumio[1072]: info: Loading plugin "airplay_emulation"... Mar 12 14:54:45 volumio-attic volumio[1072]: info: Starting Shairport Sync Mar 12 14:54:45 volumio-attic volumio[1072]: info: Loading plugin "last_100"... Mar 12 14:54:45 volumio-attic volumio[1072]: info: Loading plugin "webradio"... Mar 12 14:54:45 volumio-attic volumio[1072]: info: Loading plugin "i2s_dacs"... Mar 12 14:54:45 volumio-attic volumio[1072]: info: Loading plugin "volumiodiscovery"... Mar 12 14:54:45 volumio-attic volumio[1072]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 12 14:54:45 volumio-attic volumio[1072]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 12 14:54:45 volumio-attic volumio[1072]: *** WARNING *** For more information see Mar 12 14:54:45 volumio-attic node[1072]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 12 14:54:45 volumio-attic volumio[1072]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 12 14:54:45 volumio-attic volumio[1072]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 12 14:54:45 volumio-attic volumio[1072]: *** WARNING *** For more information see Mar 12 14:54:45 volumio-attic node[1072]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 12 14:54:45 volumio-attic node[1072]: *** WARNING *** For more information see Mar 12 14:54:45 volumio-attic node[1072]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 12 14:54:45 volumio-attic node[1072]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 12 14:54:45 volumio-attic node[1072]: *** WARNING *** For more information see Mar 12 14:54:45 volumio-attic volumio[1072]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 12 14:54:45 volumio-attic volumio[1072]: info: Discovery: Started advertising with name: Volumio attic Mar 12 14:54:45 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 12 14:54:45 volumio-attic volumio[1072]: info: Loading plugin "spop"... Mar 12 14:54:45 volumio-attic sudo[1146]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:46 volumio-attic volumio[1072]: info: Loading plugin "now_playing"... Mar 12 14:54:47 volumio-attic volumio[1072]: info: Loading plugin "outputs"... Mar 12 14:54:47 volumio-attic volumio[1072]: info: Loading plugin "albumart"... Mar 12 14:54:47 volumio-attic volumio[1072]: info: Plugin example_plugin is not enabled Mar 12 14:54:47 volumio-attic volumio[1072]: info: Loading plugin "inputs"... Mar 12 14:54:47 volumio-attic volumio[1072]: info: Loading plugin "updater_comm"... Mar 12 14:54:47 volumio-attic volumio[1072]: info: Plugin mpdemulation is not enabled Mar 12 14:54:47 volumio-attic volumio[1072]: info: Loading plugin "rest_api"... Mar 12 14:54:47 volumio-attic volumio[1072]: info: Loading plugin "websocket"... Mar 12 14:54:47 volumio-attic volumio[1072]: info: Starting Socket.io Server version 2.3.0 Mar 12 14:54:47 volumio-attic volumio[1072]: info: Loading plugin "touch_display"... Mar 12 14:54:48 volumio-attic volumio[1072]: Forking 3 albumart workers Mar 12 14:54:48 volumio-attic volumio[1072]: info: Applying required configuration parameters for plugin touch_display Mar 12 14:54:48 volumio-attic volumio[1072]: info: Loading i18n strings for locale en Mar 12 14:54:48 volumio-attic volumio[1072]: Updating browse sources language Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 14:54:48 volumio-attic sudo[1129]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:48 volumio-attic volumio[1072]: Starting albumart workers Mar 12 14:54:48 volumio-attic volumio[1072]: Starting albumart workers Mar 12 14:54:48 volumio-attic volumio[1072]: Starting albumart workers Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::initPlayerControls Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 12 14:54:48 volumio-attic volumio[1072]: Express server listening on port 3000 Mar 12 14:54:48 volumio-attic volumio[1072]: [Metrics] WebUI: 6s 852.10ms Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreStateMachine::resetVolumioState Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreStateMachine::getcurrentVolume Mar 12 14:54:48 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioRetrievevolume Mar 12 14:54:48 volumio-attic volumio[1072]: info: Volumio Network Manager: Network status updated: 2 Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to 192.168.1.65 from 192.168.1.215 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/134.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to 192.168.1.65 from 192.168.1.215 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/134.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to 192.168.1.65 from 192.168.1.215 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/134.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to 192.168.1.65:3000 from 192.168.1.217 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to 192.168.1.65:3000 from 192.168.1.217 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to 192.168.1.65:3000 from 192.168.1.217 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 12 14:54:49 volumio-attic volumio[1072]: info: VolumeController:: Volume=45 Mute =false Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreStateMachine::pushState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioPushState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreStateMachine::updateTrackBlock Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrackBlock Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioRetrievevolume Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: Reloading queue from file Mar 12 14:54:49 volumio-attic volumio[1072]: info: Setting Device type: Raspberry PI Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreStateMachine::setRepeat null single undefined Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreStateMachine::pushState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioPushState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreStateMachine::setRandom null Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreStateMachine::pushState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioPushState Mar 12 14:54:49 volumio-attic volumio[1072]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 12 14:54:49 volumio-attic volumio[1072]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115 Mar 12 14:54:49 volumio-attic volumio[1072]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Mar 12 14:54:49 volumio-attic volumio[1072]: info: Completed loading Core Plugins Mar 12 14:54:49 volumio-attic volumio[1072]: info: Preparing to generate the ALSA configuration file Mar 12 14:54:49 volumio-attic systemd[1]: systemd-fsckd.service: Succeeded. Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: VolumeController:: Volume=45 Mute =false Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreStateMachine::pushState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioPushState Mar 12 14:54:49 volumio-attic volumio[1072]: info: Asound.conf file unchanged, so no further update is needed Mar 12 14:54:49 volumio-attic volumio[1072]: info: Output device has changed, restarting MPD Mar 12 14:54:49 volumio-attic sudo[1254]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 12 14:54:49 volumio-attic volumio[1072]: info: Output device has changed, restarting Shairport Sync Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic sudo[1254]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 14:54:49 volumio-attic sudo[1254]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:49 volumio-attic sudo[1256]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 12 14:54:49 volumio-attic sudo[1256]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic systemd[1]: Stopping Music Player Daemon... Mar 12 14:54:49 volumio-attic volumio[1072]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: ___________ START PLUGINS ___________ Mar 12 14:54:49 volumio-attic volumio[1072]: info: ControllerMpd::onStart: Initializing MPD Mar 12 14:54:49 volumio-attic volumio[1072]: info: Creating MPD Configuration file Mar 12 14:54:49 volumio-attic sudo[1263]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 12 14:54:49 volumio-attic sudo[1263]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 12 14:54:49 volumio-attic volumio[1072]: info: [1741805689364] CoreMusicLibrary::Adding element Media Servers Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 14:54:49 volumio-attic sudo[1263]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:49 volumio-attic sudo[1265]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 12 14:54:49 volumio-attic sudo[1265]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 12 14:54:49 volumio-attic volumio[1072]: info: [1741805689457] CoreMusicLibrary::Adding element Last_100 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 12 14:54:49 volumio-attic volumio[1072]: info: [1741805689459] CoreMusicLibrary::Adding element Webradio Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 12 14:54:49 volumio-attic volumio[1072]: info: Initializing BBC Radios Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 14:54:49 volumio-attic sh[558]: timed out Mar 12 14:54:49 volumio-attic dhcpcd[609]: timed out Mar 12 14:54:49 volumio-attic sh[558]: dhcpcd exited Mar 12 14:54:49 volumio-attic dhcpcd[609]: dhcpcd exited Mar 12 14:54:49 volumio-attic sh[558]: ifup: failed to bring up eth0 Mar 12 14:54:49 volumio-attic systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Mar 12 14:54:49 volumio-attic systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Mar 12 14:54:49 volumio-attic volumio[1072]: info: Creating Spotify config file Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: [now-playing] ConfigUpdater: config is up to date. Mar 12 14:54:49 volumio-attic volumio[1072]: info: Loading i18n strings for locale en Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 12 14:54:49 volumio-attic volumio[1072]: info: Volumio Calling Home Mar 12 14:54:49 volumio-attic systemd[1]: mpd.service: Succeeded. Mar 12 14:54:49 volumio-attic systemd[1]: Stopped Music Player Daemon. Mar 12 14:54:49 volumio-attic sudo[1290]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Mar 12 14:54:49 volumio-attic sudo[1290]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic sudo[1292]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Mar 12 14:54:49 volumio-attic sudo[1292]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic sudo[1295]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Mar 12 14:54:49 volumio-attic sudo[1295]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic systemd[1]: Starting Music Player Daemon... Mar 12 14:54:49 volumio-attic volumio[1072]: info: [now-playing] Fetching API key... Mar 12 14:54:49 volumio-attic systemd[1]: Reloading. Mar 12 14:54:49 volumio-attic volumio[1072]: info: [now-playing] App is listening on port 4004. Mar 12 14:54:49 volumio-attic volumio[1072]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Mar 12 14:54:49 volumio-attic sudo[1287]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 12 14:54:49 volumio-attic sudo[1287]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic sudo[1287]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:49 volumio-attic volumio[1072]: info: Discovery: adding 49840f1b-238f-40bd-a9d0-2e97befbc584 Mar 12 14:54:49 volumio-attic volumio[1072]: info: Discovery: Found device Volumio attic Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: touch_display: Backlight interface detected. Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to 192.168.1.65 from 192.168.1.215 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/134.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Mar 12 14:54:49 volumio-attic volumio[1072]: info: MPD Permissions set Mar 12 14:54:49 volumio-attic volumio[1072]: info: MPD Permissions set Mar 12 14:54:49 volumio-attic volumio[1072]: info: Discovery: adding 91af4e5f-309c-4fe3-8277-ee3d522af188 Mar 12 14:54:49 volumio-attic volumio[1072]: info: Discovery: Found device Volumio barn Mar 12 14:54:49 volumio-attic volumio[1072]: info: Discovery: Connecting to remote: 192.168.1.217 Mar 12 14:54:49 volumio-attic volumio[1072]: info: Spotify config file written Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 12 14:54:49 volumio-attic sudo[1309]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 12 14:54:49 volumio-attic sudo[1309]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:49 volumio-attic volumio[1072]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 12 14:54:49 volumio-attic volumio[1072]: info: No need to fix Spotify hosts Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetVisibleSources Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 12 14:54:49 volumio-attic volumio[1072]: info: Received Get System Info Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 12 14:54:49 volumio-attic volumio[1072]: info: Discovery: Getting this device information Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 12 14:54:49 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:49 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:49 volumio-attic volumio[1072]: info: Listing playlists Mar 12 14:54:50 volumio-attic systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Mar 12 14:54:50 volumio-attic volumio[1072]: info: Volumio called home Mar 12 14:54:50 volumio-attic volumio[1072]: info: Discovery: Connected to remote: 192.168.1.217 Mar 12 14:54:50 volumio-attic volumio[1072]: info: touch_display: Raspberry Pi Foundation touch screen detected. Mar 12 14:54:50 volumio-attic sudo[1324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Mar 12 14:54:50 volumio-attic sudo[1324]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:50 volumio-attic sudo[1324]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:50 volumio-attic sudo[1326]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/rpi_backlight/brightness Mar 12 14:54:50 volumio-attic sudo[1326]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:50 volumio-attic sudo[1326]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:50 volumio-attic volumio[1072]: info: Starting Shairport Sync Mar 12 14:54:50 volumio-attic volumio[1072]: info: Starting Shairport Sync Mar 12 14:54:50 volumio-attic sudo[1330]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 12 14:54:50 volumio-attic sudo[1330]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:50 volumio-attic volumio[1072]: info: Starting Shairport Sync Mar 12 14:54:50 volumio-attic sudo[1332]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 12 14:54:50 volumio-attic sudo[1332]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:50 volumio-attic sudo[1335]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 12 14:54:50 volumio-attic sudo[1335]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:50 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:50 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:50 volumio-attic volumio[1072]: info: touch_display: File permissions for backlight brightness control set. Mar 12 14:54:50 volumio-attic volumio[1072]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Mar 12 14:54:50 volumio-attic sudo[1295]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:50 volumio-attic systemd[1]: Reloading. Mar 12 14:54:50 volumio-attic volumio[1072]: info: touch_display: systemctl daemon-reload succeeded. Mar 12 14:54:50 volumio-attic sudo[1340]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Mar 12 14:54:50 volumio-attic sudo[1340]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:50 volumio-attic systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Mar 12 14:54:50 volumio-attic sudo[1292]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:50 volumio-attic volumio[1072]: info: touch_display: systemctl disable getty@tty1.service succeeded. Mar 12 14:54:51 volumio-attic systemd[1]: Started Volumio Kiosk. Mar 12 14:54:51 volumio-attic sudo[1340]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:51 volumio-attic systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 12 14:54:51 volumio-attic volumio[1072]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Mar 12 14:54:51 volumio-attic volumio[1072]: info: touch_display: Volumio Kiosk started. Mar 12 14:54:51 volumio-attic mpd[1338]: Mar 12 14:54 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 12 14:54:51 volumio-attic systemd[1]: Started go-librespot Daemon. Mar 12 14:54:51 volumio-attic go-librespot[1358]: go-librespot daemon starting... Mar 12 14:54:51 volumio-attic sudo[1309]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:51 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:51 volumio-attic systemd[1]: shairport-sync.service: Succeeded. Mar 12 14:54:51 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:51 volumio-attic systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 12 14:54:51 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:51 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:51 volumio-attic sudo[1290]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:51 volumio-attic volumio[1072]: info: touch_display: systemctl stop getty@tty1.service succeeded. Mar 12 14:54:51 volumio-attic volumio[1072]: info: touch_display: X display number found: Mar 12 14:54:51 volumio-attic systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 12 14:54:51 volumio-attic sudo[1332]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:51 volumio-attic sudo[1335]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:51 volumio-attic sudo[1330]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:51 volumio-attic volumio[1072]: info: Shairport-Sync Started Mar 12 14:54:51 volumio-attic volumio[1072]: Error adding Membership: Error: addMembership EINVAL Mar 12 14:54:51 volumio-attic volumio[1072]: info: Shairport-Sync Started Mar 12 14:54:51 volumio-attic volumio[1072]: info: Shairport-Sync Started Mar 12 14:54:51 volumio-attic volumio[1072]: info: touch_display: X display number found: 0 Mar 12 14:54:51 volumio-attic systemd[1]: systemd-hostnamed.service: Succeeded. Mar 12 14:54:51 volumio-attic startx[1356]: X.Org X Server 1.20.4 Mar 12 14:54:51 volumio-attic startx[1356]: X Protocol Version 11, Revision 0 Mar 12 14:54:51 volumio-attic startx[1356]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian Mar 12 14:54:51 volumio-attic startx[1356]: Current Operating System: Linux volumio-attic 6.6.62-v7l+ #1816 SMP Mon Nov 18 15:33:33 GMT 2024 armv7l Mar 12 14:54:51 volumio-attic startx[1356]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory numa_policy=interleave snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=800 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 smsc95xx.macaddr=E4:5F:01:AE:37:F1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=104224f7-d7af-43f8-9bc3-0adf882b37ed imgfile=/volumio_current.sqsh bootpart=UUID=815B-E7CF datapart=UUID=16ae7c3a-95a2-4b6f-8fa1-48291dd70f30 uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Mar 12 14:54:51 volumio-attic startx[1356]: Build Date: 04 April 2023 07:50:56AM Mar 12 14:54:51 volumio-attic startx[1356]: xorg-server 2:1.20.4-1+rpt4+deb10u9 (https://www.debian.org/support) Mar 12 14:54:51 volumio-attic startx[1356]: Current version of pixman: 0.36.0 Mar 12 14:54:51 volumio-attic startx[1356]: Before reporting problems, check http://wiki.x.org Mar 12 14:54:51 volumio-attic startx[1356]: to make sure that you have the latest version. Mar 12 14:54:51 volumio-attic startx[1356]: Markers: (--) probed, (**) from config file, (==) default setting, Mar 12 14:54:51 volumio-attic startx[1356]: (++) from command line, (!!) notice, (II) informational, Mar 12 14:54:51 volumio-attic startx[1356]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Mar 12 14:54:51 volumio-attic startx[1356]: (==) Log file: "/var/log/Xorg.0.log", Time: Wed Mar 12 14:54:51 2025 Mar 12 14:54:51 volumio-attic startx[1356]: (==) Using config directory: "/etc/X11/xorg.conf.d" Mar 12 14:54:51 volumio-attic startx[1356]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Mar 12 14:54:51 volumio-attic volumio[1072]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Mar 12 14:54:51 volumio-attic volumio[1072]: info: touch_display: X display number found: 0 Mar 12 14:54:51 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:51-04:00" level=info msg="running go-librespot 0.2.0" Mar 12 14:54:51 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:51-04:00" level=debug msg="app state loaded" Mar 12 14:54:51 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:51-04:00" level=debug msg="stored credentials not found" Mar 12 14:54:51 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:51-04:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 12 14:54:52 volumio-attic volumio[1072]: info: [now-playing] OpenWeatherMap API key obtained. Mar 12 14:54:52 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:52-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 12 14:54:52 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:52-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 12 14:54:52 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:52-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 12 14:54:52 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:52-04:00" level=info msg="zeroconf server listening on port 34967" Mar 12 14:54:52 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 12 14:54:52 volumio-attic volumio[1072]: info: Discovery: Getting this device information Mar 12 14:54:52 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:52 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:52 volumio-attic volumio[1072]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 12 14:54:52 volumio-attic volumio[1072]: info: touch_display: Setting screensaver timeout to 0 seconds. Mar 12 14:54:53 volumio-attic systemd[1]: Started Music Player Daemon. Mar 12 14:54:53 volumio-attic sudo[1256]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:53 volumio-attic sudo[1265]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:53 volumio-attic volumio[1072]: info: Completed starting Core Plugins Mar 12 14:54:53 volumio-attic volumio[1072]: info: ------------------------------------------- Mar 12 14:54:53 volumio-attic volumio[1072]: info: ----- MyVolumio plugins startup ---- Mar 12 14:54:53 volumio-attic volumio[1072]: info: ------------------------------------------- Mar 12 14:54:53 volumio-attic volumio[1072]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 12 14:54:54 volumio-attic volumio[1072]: error: MPD error: The expression evaluated to a falsy value: Mar 12 14:54:54 volumio-attic volumio[1072]: assert.ok(self.idling) Mar 12 14:54:54 volumio-attic volumio[1072]: error: The expression evaluated to a falsy value: Mar 12 14:54:54 volumio-attic volumio[1072]: assert.ok(self.idling) Mar 12 14:54:54 volumio-attic volumio[1072]: info: MPD running with PID1473 1338 Mar 12 14:54:54 volumio-attic volumio[1072]: ,establishing connection Mar 12 14:54:54 volumio-attic volumio[1072]: error: updateQueue error: null Mar 12 14:54:54 volumio-attic volumio[1072]: error: updateQueue error: null Mar 12 14:54:54 volumio-attic volumio[1072]: info: go-librespot daemon successfully initialized Mar 12 14:54:54 volumio-attic sudo[1503]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 12 14:54:54 volumio-attic sudo[1503]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:54 volumio-attic sudo[1503]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:54 volumio-attic sudo[1506]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 12 14:54:54 volumio-attic sudo[1506]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:54 volumio-attic sudo[1506]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:54 volumio-attic sudo[1509]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 12 14:54:54 volumio-attic sudo[1509]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 12 14:54:54 volumio-attic systemd[1]: Started UPnP Renderer front-end to MPD. Mar 12 14:54:54 volumio-attic sudo[1509]: pam_unix(sudo:session): session closed for user root Mar 12 14:54:54 volumio-attic volumio[1072]: info: Upmpdcli Daemon Started Mar 12 14:54:54 volumio-attic volumio[1511]: Generating RSA private key, 4096 bit long modulus (2 primes) Mar 12 14:54:55 volumio-attic volumio[1072]: verbose: New Socket.io Connection to 192.168.1.65:3000 from 192.168.1.217 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Mar 12 14:54:57 volumio-attic volumio[1072]: info: Initializing connection to go-librespot Websocket Mar 12 14:54:57 volumio-attic volumio[1072]: info: Connection to go-librespot Websocket established Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="new websocket client" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="obtained new client token: AAD6Ny3uzuvmSMk5ixay2dJlDurRqNhUABLtxt4Re0pawfc815VGAF15DVzwF0u2+sDdPxH3juQKnI1jWcsDpt2veLvR48DYzde21uUK1N9WcN/M6nnBlpVGZ1ytCfOa/WqG0T3MCfmVTxSvhbvq9S+WFWt8EcDHX0WJT/UZwWdnNSqRq15S2DlMI2z8uS2YgxHslxQj28/jZqabddaai8uddE2VfgghSwKM5vUNP2JrLHwJfCaqouc+3g==" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="completed keyexchange" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="completed challenge" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=info msg="authenticated AP as 31t44d5scnxm2w5rngt2s4oovf5e" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=info msg="authenticated Login5 as 31t44d5scnxm2w5rngt2s4oovf5e" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=info msg="accepted zeroconf user 31t44d5scnxm2w5rngt2s4oovf5e from RAINER2022" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="dealer connection opened" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=trace msg="starting accesspoint recv loop" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=trace msg="starting dealer recv loop" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=trace msg="received accesspoint ping" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="received connection id: MGViOGU4ZGItOTYxYS00MThmLTgwNWItNmE1Y2ZiZmFlMmRmK2RlYWxlcit0Y3A6Ly8wYWNiZjkyYS5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArODZBQUNCQkNGRTZFQ0M5NTcwRUVEMTRDRTZCMTIzNDU5NEM0MDlBMEZERjJGNjYyMkUxNDNFRTQ4Mjg4MzY5OQ==" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=trace msg="received accesspoint pong ack" Mar 12 14:54:57 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:57-04:00" level=debug msg="put connect state because NEW_DEVICE" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="handling transfer player command from 37c1c00b3816d639f139fef8f25af8585f491301" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="resolved context of track" uri="spotify:playlist:6qz6p26vDY2ZYxGfB0Ewxt" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=trace msg="fetched new page 0 with 7 items (list: 7)" uri="spotify:playlist:6qz6p26vDY2ZYxGfB0Ewxt" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="loading track (paused: false, position: 147603ms)" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=trace msg="emitting websocket event: will_play" Mar 12 14:54:58 volumio-attic volumio[1072]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4bkPAARkDov1lV05emEF7a","play_origin":"playlist"}} Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="selected format OGG_VORBIS_320 (a3ddc2c04b861b13020c997dbe8ea31cc8fe1da3)" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="requested aes key for file a3ddc2c04b861b13020c997dbe8ea31cc8fe1da3, gid: 4bkPAARkDov1lV05emEF7a" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1392" Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1143" Mar 12 14:54:58 volumio-attic volumio-remote-updater[679]: [2025-03-12 14:54:58] [connect] Successful connection Mar 12 14:54:58 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:58-04:00" level=debug msg="fetched first chunk of 16, total size is 7922892 bytes" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:58 volumio-attic volumio-remote-updater[679]: [2025-03-12 14:54:58] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1741805698 101 Mar 12 14:54:58 volumio-attic volumio[1072]: 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: 11 Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="fetched chunk 15/15, size: 58572" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="fetched chunk 12/15, size: 524288" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=trace msg="seek to 147603ms (diff: 93ms, samples: 6509292, bytes: 6354285)" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="created new output device" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04: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" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=info msg="loaded track \"Soft Spine\" (paused: false, position: 147603ms, duration: 183990ms, prefetched: false)" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:59 volumio-attic volumio[1511]: ...............................................++++ Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=trace msg="emitting websocket event: metadata" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="prefetching next track" uri="spotify:track:2hIgUd40Nqs1TrGbtVcogt" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=trace msg="emitting websocket event: active" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="sending successful reply for dealer request" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 12 14:54:59 volumio-attic volumio[1072]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4bkPAARkDov1lV05emEF7a","name":"Soft Spine","artist_names":["Spiritbox"],"album_name":"Tsunami Sea","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ca5c3280d995a78c34bdf210","position":147603,"duration":183990,"release_date":"year:2025 month:3 day:7","track_number":5,"disc_number":1}} Mar 12 14:54:59 volumio-attic volumio[1072]: SPOTIFY: received: {"type":"active","data":null} Mar 12 14:54:59 volumio-attic volumio[1072]: info: Aligning Spotify Volume to Volumio Volume Mar 12 14:54:59 volumio-attic volumio[1072]: info: CoreCommandRouter::volumioGetState Mar 12 14:54:59 volumio-attic volumio[1072]: info: CorePlayQueue::getTrack 0 Mar 12 14:54:59 volumio-attic volumio[1072]: info: Setting Spotify Volume from Volumio: 45 Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="selected format OGG_VORBIS_320 (7df8fd3b0f51b4906c42220024c774259684fea3)" uri="spotify:track:2hIgUd40Nqs1TrGbtVcogt" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="requested aes key for file 7df8fd3b0f51b4906c42220024c774259684fea3, gid: 2hIgUd40Nqs1TrGbtVcogt" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=trace msg="emitting websocket event: playing" Mar 12 14:54:59 volumio-attic volumio[1072]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4bkPAARkDov1lV05emEF7a","play_origin":"playlist"}} Mar 12 14:54:59 volumio-attic volumio[1072]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 12 14:54:59 volumio-attic volumio[1072]: TypeError: Cannot read property 'service' of undefined Mar 12 14:54:59 volumio-attic volumio[1072]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) Mar 12 14:54:59 volumio-attic volumio[1072]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) Mar 12 14:54:59 volumio-attic volumio[1072]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) Mar 12 14:54:59 volumio-attic volumio[1072]: at WebSocket.emit (events.js:315:20) Mar 12 14:54:59 volumio-attic volumio[1072]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 12 14:54:59 volumio-attic volumio[1072]: at Receiver.emit (events.js:315:20) Mar 12 14:54:59 volumio-attic volumio[1072]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 12 14:54:59 volumio-attic volumio[1072]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 12 14:54:59 volumio-attic volumio[1072]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 12 14:54:59 volumio-attic volumio[1072]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 12 14:54:59 volumio-attic volumio[1072]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 12 14:54:59 volumio-attic volumio[1072]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 12 14:54:59 volumio-attic volumio[1072]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 12 14:54:59 volumio-attic volumio[1072]: at Socket.emit (events.js:315:20) Mar 12 14:54:59 volumio-attic volumio[1072]: at addChunk (internal/streams/readable.js:309:12) Mar 12 14:54:59 volumio-attic volumio[1072]: at readableAddChunk (internal/streams/readable.js:284:9) Mar 12 14:54:59 volumio-attic volumio[1072]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="fetched chunk 14/15, size: 524288" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:54:59 volumio-attic go-librespot[1358]: time="2025-03-12T14:54:59-04:00" level=debug msg="fetched chunk 13/15, size: 524288" uri="spotify:track:4bkPAARkDov1lV05emEF7a" Mar 12 14:55:00 volumio-attic go-librespot[1358]: time="2025-03-12T14:55:00-04:00" level=debug msg="fetched first chunk of 21, total size is 10761091 bytes" uri="spotify:track:2hIgUd40Nqs1TrGbtVcogt" Mar 12 14:55:00 volumio-attic go-librespot[1358]: time="2025-03-12T14:55:00-04:00" level=info msg="prefetched track \"No Kings - No Masters\" (duration: 250842ms)" uri="spotify:track:2hIgUd40Nqs1TrGbtVcogt" Mar 12 14:55:00 volumio-attic sudo[1650]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-12 14:54 Mar 12 14:55:00 volumio-attic sudo[1650]: 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"