-- Logs begin at Sun 2024-11-24 11:10:55 UTC, end at Sun 2025-03-09 16:49:05 UTC. -- Mar 09 16:48:49 volumio-eddy systemd-timedated[1102]: Changed local time to Sun Mar 9 16:48:49 2025 Mar 09 16:48:49 volumio-eddy sudo[1085]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:49 volumio-eddy systemd[1]: Starting Daily man-db regeneration... Mar 09 16:48:49 volumio-eddy systemd[1]: Starting Daily apt download activities... Mar 09 16:48:49 volumio-eddy volumio-time-update[577]: volumio-time-update-util: System time updated successfully. Mar 09 16:48:49 volumio-eddy systemd[1]: Started Volumio Time Update Utility. Mar 09 16:48:49 volumio-eddy wireless.js[559]: trying... Mar 09 16:48:49 volumio-eddy systemd[1]: man-db.service: Succeeded. Mar 09 16:48:49 volumio-eddy systemd[1]: Started Daily man-db regeneration. Mar 09 16:48:49 volumio-eddy sudo[1113]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 09 16:48:49 volumio-eddy sudo[1113]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:49 volumio-eddy sudo[1113]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:49 volumio-eddy systemd[1]: apt-daily.service: Succeeded. Mar 09 16:48:49 volumio-eddy systemd[1]: Started Daily apt download activities. Mar 09 16:48:49 volumio-eddy systemd[1]: Starting Daily apt upgrade and clean activities... Mar 09 16:48:49 volumio-eddy ntpd[1099]: Soliciting pool server 194.104.0.153 Mar 09 16:48:49 volumio-eddy dhcpcd[1100]: wlan0: leased 192.168.178.248 for 86400 seconds Mar 09 16:48:49 volumio-eddy dhcpcd[1100]: wlan0: adding route to 192.168.178.0/24 Mar 09 16:48:49 volumio-eddy dhcpcd[1100]: wlan0: adding default route via 192.168.178.1 Mar 09 16:48:49 volumio-eddy avahi-daemon[584]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.248. Mar 09 16:48:49 volumio-eddy avahi-daemon[584]: New relevant interface wlan0.IPv4 for mDNS. Mar 09 16:48:49 volumio-eddy avahi-daemon[584]: Registering new address record for 192.168.178.248 on wlan0.IPv4. Mar 09 16:48:50 volumio-eddy ntpd[1099]: ntpd exiting on signal 15 (Terminated) Mar 09 16:48:50 volumio-eddy ntpd[1099]: 194.104.0.153 local addr 192.168.178.192 -> Mar 09 16:48:50 volumio-eddy systemd[1]: Stopping Network Time Service... Mar 09 16:48:50 volumio-eddy systemd[1]: ntp.service: Succeeded. Mar 09 16:48:50 volumio-eddy systemd[1]: Stopped Network Time Service. Mar 09 16:48:50 volumio-eddy wireless.js[559]: trying... Mar 09 16:48:50 volumio-eddy systemd[1]: Starting Network Time Service... Mar 09 16:48:50 volumio-eddy nmbd[759]: [2025/03/09 16:48:50.115521, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 09 16:48:50 volumio-eddy kernel: nf_conntrack: automatic helper assignment is deprecated and it will be removed soon. Use the iptables CT target to attach helpers instead. Mar 09 16:48:50 volumio-eddy systemd[1]: Started Samba NMB Daemon. Mar 09 16:48:50 volumio-eddy nmbd[759]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Mar 09 16:48:50 volumio-eddy systemd[1]: Starting Samba Winbind Daemon... Mar 09 16:48:50 volumio-eddy sudo[1239]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 09 16:48:50 volumio-eddy ntpd[1238]: ntpd 4.2.8p12@1.3728-o (1): Starting Mar 09 16:48:50 volumio-eddy ntpd[1238]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Mar 09 16:48:50 volumio-eddy systemd[1]: Started Network Time Service. Mar 09 16:48:50 volumio-eddy ntpd[1252]: proto: precision = 0.875 usec (-20) Mar 09 16:48:50 volumio-eddy ntpd[1252]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Mar 09 16:48:50 volumio-eddy ntpd[1252]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Mar 09 16:48:50 volumio-eddy ntpd[1252]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 803 days ago Mar 09 16:48:50 volumio-eddy ntpd[1252]: Listen and drop on 0 v6wildcard [::]:123 Mar 09 16:48:50 volumio-eddy ntpd[1252]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Mar 09 16:48:50 volumio-eddy ntpd[1252]: Listen normally on 2 lo 127.0.0.1:123 Mar 09 16:48:50 volumio-eddy ntpd[1252]: Listen normally on 3 eth0 192.168.178.192:123 Mar 09 16:48:50 volumio-eddy ntpd[1252]: Listen normally on 4 wlan0 192.168.178.248:123 Mar 09 16:48:50 volumio-eddy ntpd[1252]: Listening on routing socket on fd #21 for interface updates Mar 09 16:48:50 volumio-eddy ntpd[1252]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Mar 09 16:48:50 volumio-eddy ntpd[1252]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Mar 09 16:48:50 volumio-eddy sudo[1239]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:50 volumio-eddy sudo[1239]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:50 volumio-eddy wireless.js[559]: Connected to: ----Ziggo5430581 Mar 09 16:48:50 volumio-eddy wireless.js[559]: ---- Mar 09 16:48:50 volumio-eddy sudo[1265]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 09 16:48:50 volumio-eddy sudo[1265]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:50 volumio-eddy sudo[1265]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:50 volumio-eddy wireless.js[559]: ... joined AP, wlan0 IPv4 is 192.168.178.248, ipV6 is undefined Mar 09 16:48:50 volumio-eddy wireless.js[559]: It's done! AP Mar 09 16:48:50 volumio-eddy systemd[1]: apt-daily-upgrade.service: Succeeded. Mar 09 16:48:50 volumio-eddy systemd[1]: Started Daily apt upgrade and clean activities. Mar 09 16:48:50 volumio-eddy iwconfig[1284]: Error for wireless request "Set Power Management" (8B2C) : Mar 09 16:48:50 volumio-eddy iwconfig[1284]: SET failed on device wlan0 ; Operation not permitted. Mar 09 16:48:50 volumio-eddy systemd[1]: Started Wireless Services. Mar 09 16:48:50 volumio-eddy systemd[1]: Started Volumio Backend Module. Mar 09 16:48:50 volumio-eddy systemd[1]: Started Volumio Cpu Tweaker. Mar 09 16:48:50 volumio-eddy systemd[1]: Started Start Volumio Kiosk. Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: Starting Volumio Kiosk with arguments for cursor display Mar 09 16:48:50 volumio-eddy volumio-cpu-tweak[1286]: Setting RT Priority for mpd Mar 09 16:48:50 volumio-eddy volumio-cpu-tweak[1286]: Setting MPD Affinity Mar 09 16:48:50 volumio-eddy volumio-cpu-tweak[1286]: pid 820's current affinity mask: f Mar 09 16:48:50 volumio-eddy volumio-cpu-tweak[1286]: pid 820's new affinity mask: 3 Mar 09 16:48:50 volumio-eddy volumio-cpu-tweak[1286]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Mar 09 16:48:50 volumio-eddy volumio-cpu-tweak[1286]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Mar 09 16:48:50 volumio-eddy systemd[1]: volumio_cpu_tweak.service: Succeeded. Mar 09 16:48:50 volumio-eddy winbindd[1246]: [2025/03/09 16:48:50.382284, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Mar 09 16:48:50 volumio-eddy winbindd[1246]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 09 16:48:50 volumio-eddy winbindd[1246]: [2025/03/09 16:48:50.391947, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 09 16:48:50 volumio-eddy systemd[1]: Started Samba Winbind Daemon. Mar 09 16:48:50 volumio-eddy winbindd[1246]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Mar 09 16:48:50 volumio-eddy systemd[1]: Starting Samba SMB Daemon... Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: X.Org X Server 1.20.4 Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: X Protocol Version 11, Revision 0 Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: Build Operating System: Linux 4.19.0-18-armmp-lpae armv7l Debian Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: Current Operating System: Linux volumio-eddy 4.4.71+ #23 SMP Sun Sep 20 12:23:26 CEST 2020 armv7l Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: Kernel command line: earlyprintk quiet loglevel=0 splash plymouth.ignore-serial-consoles initramfs.clear console=tty1 console=ttyS3,115200n8 rw init=/sbin/init imgpart=UUID=9a4ddb3d-db44-44c2-8b32-71fe74cb4a6a imgfile=/volumio_current.sqsh bootpart=UUID=6393-5E0E datapart=UUID=1c099cb2-4851-4edb-9664-eeb2aaebfdd2 uuidconfig=/extlinux/extlinux.conf vt.global_cursor_default=0 bootdelay=5 uboot_version=2017.07-g879646d1d6 root=/dev/mmcblk1p2 Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: Build Date: 18 December 2021 09:05:36AM Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: xorg-server 2:1.20.4-1+deb10u4 (https://www.debian.org/support) Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: Current version of pixman: 0.36.0 Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: Before reporting problems, check http://wiki.x.org Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: to make sure that you have the latest version. Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: Markers: (--) probed, (**) from config file, (==) default setting, Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: (++) from command line, (!!) notice, (II) informational, Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: (==) Log file: "/var/log/Xorg.0.log", Time: Sun Mar 9 16:48:50 2025 Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: gbm: failed to open any driver (search paths /usr/lib/arm-linux-gnueabihf/dri:\$${ORIGIN}/dri:/usr/lib/dri) Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: gbm: Last dlopen error: /usr/lib/dri/rockchip_dri.so: cannot open shared object file: No such file or directory Mar 09 16:48:50 volumio-eddy startkiosk.sh[1287]: failed to load driver: rockchip Mar 09 16:48:50 volumio-eddy sh[494]: eth0: leased 192.168.178.192 for 86400 seconds Mar 09 16:48:50 volumio-eddy sh[494]: eth0: adding route to 192.168.178.0/24 Mar 09 16:48:50 volumio-eddy sh[494]: eth0: adding default route via 192.168.178.1 Mar 09 16:48:50 volumio-eddy dhcpcd[538]: eth0: leased 192.168.178.192 for 86400 seconds Mar 09 16:48:50 volumio-eddy dhcpcd[538]: eth0: adding route to 192.168.178.0/24 Mar 09 16:48:50 volumio-eddy dhcpcd[538]: eth0: adding default route via 192.168.178.1 Mar 09 16:48:50 volumio-eddy sh[494]: Warning: The unit file, source configuration file or drop-ins of systemd-timesyncd.service changed on disk. Run 'systemctl daemon-reload' to reload units. Mar 09 16:48:50 volumio-eddy ntpd[1252]: ntpd exiting on signal 15 (Terminated) Mar 09 16:48:50 volumio-eddy systemd[1]: Stopping Network Time Service... Mar 09 16:48:50 volumio-eddy systemd[1]: ntp.service: Succeeded. Mar 09 16:48:50 volumio-eddy systemd[1]: Stopped Network Time Service. Mar 09 16:48:50 volumio-eddy systemd[1]: Starting Network Time Service... Mar 09 16:48:50 volumio-eddy systemd[1]: Started Samba SMB Daemon. Mar 09 16:48:50 volumio-eddy smbd[1329]: [2025/03/09 16:48:50.815941, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 09 16:48:50 volumio-eddy smbd[1329]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Mar 09 16:48:50 volumio-eddy ntpd[1368]: ntpd 4.2.8p12@1.3728-o (1): Starting Mar 09 16:48:50 volumio-eddy ntpd[1368]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Mar 09 16:48:50 volumio-eddy systemd[1]: Started Network Time Service. Mar 09 16:48:50 volumio-eddy ntpd[1375]: proto: precision = 0.583 usec (-21) Mar 09 16:48:50 volumio-eddy ntpd[1375]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Mar 09 16:48:50 volumio-eddy ntpd[1375]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Mar 09 16:48:50 volumio-eddy ntpd[1375]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 803 days ago Mar 09 16:48:50 volumio-eddy ntpd[1375]: Listen and drop on 0 v6wildcard [::]:123 Mar 09 16:48:50 volumio-eddy ntpd[1375]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Mar 09 16:48:50 volumio-eddy ntpd[1375]: Listen normally on 2 lo 127.0.0.1:123 Mar 09 16:48:50 volumio-eddy ntpd[1375]: Listen normally on 3 eth0 192.168.178.192:123 Mar 09 16:48:50 volumio-eddy ntpd[1375]: Listen normally on 4 wlan0 192.168.178.248:123 Mar 09 16:48:50 volumio-eddy ntpd[1375]: Listening on routing socket on fd #21 for interface updates Mar 09 16:48:50 volumio-eddy ntpd[1375]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Mar 09 16:48:50 volumio-eddy ntpd[1375]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Mar 09 16:48:50 volumio-eddy sh[494]: forked to background, child pid 1377 Mar 09 16:48:50 volumio-eddy dhcpcd[538]: forked to background, child pid 1377 Mar 09 16:48:50 volumio-eddy ifplugd(eth0)[784]: client: ifup: interface eth0 already configured Mar 09 16:48:50 volumio-eddy sh[494]: eth0=eth0 Mar 09 16:48:51 volumio-eddy ifplugd(eth0)[784]: Program executed successfully. Mar 09 16:48:51 volumio-eddy ifplugd[751]: Network Interface Plugging Daemon...start eth0...done. Mar 09 16:48:51 volumio-eddy systemd[1]: Started LSB: Brings up/down network automatically. Mar 09 16:48:51 volumio-eddy systemd[1]: Reached target Multi-User System. Mar 09 16:48:51 volumio-eddy systemd[1]: Reached target Graphical Interface. Mar 09 16:48:51 volumio-eddy systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 09 16:48:51 volumio-eddy systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 09 16:48:51 volumio-eddy systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 09 16:48:51 volumio-eddy systemd[1]: Startup finished in 14.584s (kernel) + 14.806s (userspace) = 29.391s. Mar 09 16:48:51 volumio-eddy startkiosk.sh[1287]: (II) modeset(0): Initializing kms color map for depth 24, 8 bpc. Mar 09 16:48:51 volumio-eddy ntpd[1375]: Soliciting pool server 185.51.192.63 Mar 09 16:48:51 volumio-eddy volumio-remote-updater[563]: [2025-03-09 16:48:51] [connect] Successful connection Mar 09 16:48:52 volumio-eddy volumio[1285]: info: ------------------------------------------- Mar 09 16:48:52 volumio-eddy volumio[1285]: info: ----- Volumio3 ---- Mar 09 16:48:52 volumio-eddy volumio[1285]: info: ------------------------------------------- Mar 09 16:48:52 volumio-eddy volumio[1285]: info: ----- System startup ---- Mar 09 16:48:52 volumio-eddy volumio[1285]: info: ------------------------------------------- Mar 09 16:48:52 volumio-eddy ntpd[1375]: Soliciting pool server 185.51.192.61 Mar 09 16:48:52 volumio-eddy ntpd[1375]: Soliciting pool server 193.123.38.172 Mar 09 16:48:53 volumio-eddy volumio[1285]: info: MYVOLUMIO Environment detected Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Plugin folders cleanup Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning into folder /volumio/app/plugins/ Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning category audio_interface Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning category miscellanea Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning category music_service Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning category plugins.json Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning category system_controller Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning category user_interface Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning into folder /data/plugins/ Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Scanning category music_service Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Plugin folders cleanup completed Mar 09 16:48:53 volumio-eddy volumio[1285]: info: ------------------------------------------- Mar 09 16:48:53 volumio-eddy volumio[1285]: info: ----- Core plugins startup ---- Mar 09 16:48:53 volumio-eddy volumio[1285]: info: ------------------------------------------- Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Loading plugins from folder /volumio/app/plugins/ Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Adding plugin upnp to MyMusic Plugins Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Loading plugins from folder /data/plugins/ Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Loading plugin "system"... Mar 09 16:48:53 volumio-eddy volumio[1285]: info: Loading plugin "appearance"... Mar 09 16:48:53 volumio-eddy ntpd[1375]: Soliciting pool server 185.224.145.68 Mar 09 16:48:53 volumio-eddy ntpd[1375]: Soliciting pool server 45.138.55.60 Mar 09 16:48:53 volumio-eddy ntpd[1375]: Soliciting pool server 213.239.154.12 Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "network"... Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Refreshing Cached IP Addresses Mar 09 16:48:54 volumio-eddy sudo[1481]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 09 16:48:54 volumio-eddy sudo[1483]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "services"... Mar 09 16:48:54 volumio-eddy sudo[1481]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "alsa_controller"... Mar 09 16:48:54 volumio-eddy sudo[1481]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:54 volumio-eddy sudo[1483]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:54 volumio-eddy sudo[1494]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 09 16:48:54 volumio-eddy sudo[1483]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:54 volumio-eddy sudo[1494]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:54 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "wizard"... Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "networkfs"... Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Starting Udev Watcher for removable devices Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Ignoring mount for partition: BOOT Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Ignoring mount for partition: volumio Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Ignoring mount for partition: volumio_data Mar 09 16:48:54 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "volumio_command_line_client"... Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "upnp"... Mar 09 16:48:54 volumio-eddy volumio[1285]: info: [1741538934394] Starting Upmpd Daemon Mar 09 16:48:54 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "my_music"... Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "mpd"... Mar 09 16:48:54 volumio-eddy sudo[1494]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "upnp_browser"... Mar 09 16:48:54 volumio-eddy ntpd[1375]: Soliciting pool server 185.224.145.68 Mar 09 16:48:54 volumio-eddy ntpd[1375]: Soliciting pool server 45.138.55.61 Mar 09 16:48:54 volumio-eddy ntpd[1375]: Soliciting pool server 178.215.228.24 Mar 09 16:48:54 volumio-eddy volumio[1285]: info: Loading plugin "alarm-clock"... Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Loading plugin "airplay_emulation"... Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Starting Shairport Sync Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Loading plugin "last_100"... Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Loading plugin "webradio"... Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Loading plugin "i2s_dacs"... Mar 09 16:48:55 volumio-eddy volumio[1285]: info: I2S DAC not set, start Auto-detection Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Loading plugin "volumiodiscovery"... Mar 09 16:48:55 volumio-eddy volumio[1285]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 09 16:48:55 volumio-eddy volumio[1285]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 09 16:48:55 volumio-eddy volumio[1285]: *** WARNING *** For more information see Mar 09 16:48:55 volumio-eddy volumio[1285]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 09 16:48:55 volumio-eddy volumio[1285]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 09 16:48:55 volumio-eddy node[1285]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 09 16:48:55 volumio-eddy volumio[1285]: *** WARNING *** For more information see Mar 09 16:48:55 volumio-eddy node[1285]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 09 16:48:55 volumio-eddy node[1285]: *** WARNING *** For more information see Mar 09 16:48:55 volumio-eddy node[1285]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 09 16:48:55 volumio-eddy node[1285]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 09 16:48:55 volumio-eddy node[1285]: *** WARNING *** For more information see Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Discovery: Started advertising with name: Volumio Eddy Mar 09 16:48:55 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Loading plugin "spop"... Mar 09 16:48:55 volumio-eddy ntpd[1375]: Soliciting pool server 162.159.200.1 Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Loading plugin "outputs"... Mar 09 16:48:55 volumio-eddy volumio[1285]: info: Loading plugin "albumart"... Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Plugin example_plugin is not enabled Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Loading plugin "inputs"... Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Loading plugin "updater_comm"... Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Plugin mpdemulation is not enabled Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Loading plugin "rest_api"... Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Loading plugin "websocket"... Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Starting Socket.io Server version 2.3.0 Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Loading i18n strings for locale nl Mar 09 16:48:56 volumio-eddy volumio[1285]: Updating browse sources language Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 09 16:48:56 volumio-eddy volumio[1285]: Forking 3 albumart workers Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::initPlayerControls Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: Express server listening on port 3000 Mar 09 16:48:56 volumio-eddy volumio[1285]: [Metrics] WebUI: 4s 757.15ms Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreStateMachine::resetVolumioState Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreStateMachine::getcurrentVolume Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioRetrievevolume Mar 09 16:48:56 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 09 16:48:56 volumio-eddy volumio[1285]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Completed loading Core Plugins Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Preparing to generate the ALSA configuration file Mar 09 16:48:56 volumio-eddy volumio[1285]: info: Volumio Network Manager: Network status updated: 3 Mar 09 16:48:56 volumio-eddy volumio-remote-updater[563]: [2025-03-09 16:48:56] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1741538931 101 Mar 09 16:48:56 volumio-eddy volumio[1285]: 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 09 16:48:56 volumio-eddy ntpd[1375]: Soliciting pool server 82.94.235.106 Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Setting Device type: Tinkerboard Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreStateMachine::setRepeat null single undefined Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreStateMachine::pushState Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CorePlayQueue::getTrack 0 Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioPushState Mar 09 16:48:57 volumio-eddy volumio[1285]: Starting albumart workers Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreStateMachine::setRandom true Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreStateMachine::pushState Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CorePlayQueue::getTrack 0 Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioPushState Mar 09 16:48:57 volumio-eddy volumio[1285]: Starting albumart workers Mar 09 16:48:57 volumio-eddy volumio[1285]: Starting albumart workers Mar 09 16:48:57 volumio-eddy volumio[1285]: info: VolumeController:: Volume=99 Mute =false Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreStateMachine::pushState Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CorePlayQueue::getTrack 0 Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioPushState Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreStateMachine::updateTrackBlock Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CorePlayQueue::getTrackBlock Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioRetrievevolume Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Asound.conf file written Mar 09 16:48:57 volumio-eddy sudo[1586]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Mar 09 16:48:57 volumio-eddy sudo[1586]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:57 volumio-eddy sudo[1586]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Output device has changed, restarting MPD Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Output device has changed, restarting Shairport Sync Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 09 16:48:57 volumio-eddy sudo[1608]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 09 16:48:57 volumio-eddy sudo[1608]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:57 volumio-eddy sudo[1610]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 09 16:48:57 volumio-eddy sudo[1608]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:57 volumio-eddy sudo[1610]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:57 volumio-eddy volumio[1285]: info: ___________ START PLUGINS ___________ Mar 09 16:48:57 volumio-eddy volumio[1285]: info: ControllerMpd::onStart: Initializing MPD Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Creating MPD Configuration file Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 09 16:48:57 volumio-eddy volumio[1285]: info: [1741538937473] CoreMusicLibrary::Adding element Media Servers Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 09 16:48:57 volumio-eddy systemd[1]: Stopping Music Player Daemon... Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 09 16:48:57 volumio-eddy sudo[1628]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 09 16:48:57 volumio-eddy sudo[1630]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 09 16:48:57 volumio-eddy sudo[1628]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 09 16:48:57 volumio-eddy sudo[1630]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:57 volumio-eddy sudo[1628]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:57 volumio-eddy systemd[1]: mpd.service: Succeeded. Mar 09 16:48:57 volumio-eddy systemd[1]: Stopped Music Player Daemon. Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 09 16:48:57 volumio-eddy volumio[1285]: info: [1741538937701] CoreMusicLibrary::Adding element Last_100 Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 09 16:48:57 volumio-eddy systemd[1]: Starting Music Player Daemon... Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 09 16:48:57 volumio-eddy volumio[1285]: info: [1741538937705] CoreMusicLibrary::Adding element Webradio Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Initializing BBC Radios Mar 09 16:48:57 volumio-eddy sudo[1673]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 09 16:48:57 volumio-eddy sudo[1673]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Creating Spotify config file Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:57 volumio-eddy sudo[1673]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Volumio Calling Home Mar 09 16:48:57 volumio-eddy ntpd[1375]: Soliciting pool server 45.83.205.227 Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Discovery: adding 941b309f-3f40-4066-82ae-52a37fd351db Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Discovery: Found device Volumio Eddy Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioGetState Mar 09 16:48:57 volumio-eddy volumio[1285]: info: CorePlayQueue::getTrack 0 Mar 09 16:48:57 volumio-eddy volumio[1285]: info: Volumio called home Mar 09 16:48:57 volumio-eddy volumio[1285]: info: MPD Permissions set Mar 09 16:48:57 volumio-eddy volumio[1285]: info: MPD Permissions set Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Spotify config file written Mar 09 16:48:58 volumio-eddy volumio[1285]: 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 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy sudo[1700]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Mar 09 16:48:58 volumio-eddy sudo[1700]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Mar 09 16:48:58 volumio-eddy systemd[1]: Started go-librespot Daemon. Mar 09 16:48:58 volumio-eddy sudo[1700]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 09 16:48:58 volumio-eddy volumio[1285]: info: No need to fix Spotify hosts Mar 09 16:48:58 volumio-eddy go-librespot[1726]: Librespot-go daemon starting... Mar 09 16:48:58 volumio-eddy volumio[1285]: info: VolumeController:: Volume=99 Mute =false Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreStateMachine::pushState Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CorePlayQueue::getTrack 0 Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioPushState Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Discovery: this is already registered, 941b309f-3f40-4066-82ae-52a37fd351db Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Discovery: Found device Volumio Eddy Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioGetState Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CorePlayQueue::getTrack 0 Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Starting Shairport Sync Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Starting Shairport Sync Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Starting Shairport Sync Mar 09 16:48:58 volumio-eddy sudo[1741]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 09 16:48:58 volumio-eddy sudo[1738]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CoreCommandRouter::volumioGetState Mar 09 16:48:58 volumio-eddy volumio[1285]: info: CorePlayQueue::getTrack 0 Mar 09 16:48:58 volumio-eddy go-librespot[1726]: time="2025-03-09T16:48:58Z" level=info msg="generated new device id: 9975986ec95a2a501d4f26c1c6083fd35d7619dd" Mar 09 16:48:58 volumio-eddy sudo[1744]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 09 16:48:58 volumio-eddy sudo[1741]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:58 volumio-eddy sudo[1738]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:58 volumio-eddy systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 09 16:48:58 volumio-eddy systemd[1]: shairport-sync.service: Succeeded. Mar 09 16:48:58 volumio-eddy sudo[1744]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:48:58 volumio-eddy systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 09 16:48:58 volumio-eddy systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 09 16:48:58 volumio-eddy sudo[1741]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:58 volumio-eddy systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 09 16:48:58 volumio-eddy systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Mar 09 16:48:58 volumio-eddy systemd[1]: shairport-sync.service: Succeeded. Mar 09 16:48:58 volumio-eddy systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 09 16:48:58 volumio-eddy systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 09 16:48:58 volumio-eddy sudo[1738]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Shairport-Sync Started Mar 09 16:48:58 volumio-eddy volumio[1285]: Error adding Membership: Error: addMembership EINVAL Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Shairport-Sync Started Mar 09 16:48:58 volumio-eddy systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 09 16:48:58 volumio-eddy systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Mar 09 16:48:58 volumio-eddy systemd[1]: shairport-sync.service: Succeeded. Mar 09 16:48:58 volumio-eddy systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 09 16:48:58 volumio-eddy systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 09 16:48:58 volumio-eddy sudo[1744]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:58 volumio-eddy volumio[1285]: info: Shairport-Sync Started Mar 09 16:48:58 volumio-eddy go-librespot[1726]: time="2025-03-09T16:48:58Z" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 09 16:48:58 volumio-eddy go-librespot[1726]: time="2025-03-09T16:48:58Z" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 09 16:48:58 volumio-eddy go-librespot[1726]: time="2025-03-09T16:48:58Z" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 09 16:48:58 volumio-eddy go-librespot[1726]: time="2025-03-09T16:48:58Z" level=debug msg="zeroconf server listening on port 40938" Mar 09 16:48:58 volumio-eddy ntpd[1375]: Soliciting pool server 188.212.113.203 Mar 09 16:48:59 volumio-eddy mpd[1697]: Mar 09 16:48 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 09 16:48:59 volumio-eddy systemd[1]: Started Music Player Daemon. Mar 09 16:48:59 volumio-eddy sudo[1610]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:59 volumio-eddy sudo[1630]: pam_unix(sudo:session): session closed for user root Mar 09 16:48:59 volumio-eddy volumio[1285]: info: Completed starting Core Plugins Mar 09 16:48:59 volumio-eddy volumio[1285]: info: ------------------------------------------- Mar 09 16:48:59 volumio-eddy volumio[1285]: info: ----- MyVolumio plugins startup ---- Mar 09 16:48:59 volumio-eddy volumio[1285]: info: ------------------------------------------- Mar 09 16:48:59 volumio-eddy volumio[1285]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 09 16:48:59 volumio-eddy volumio[1285]: error: MPD error: The expression evaluated to a falsy value: Mar 09 16:48:59 volumio-eddy volumio[1285]: assert.ok(self.idling) Mar 09 16:48:59 volumio-eddy volumio[1285]: error: The expression evaluated to a falsy value: Mar 09 16:48:59 volumio-eddy volumio[1285]: assert.ok(self.idling) Mar 09 16:48:59 volumio-eddy volumio[1285]: info: MPD running with PID1697 Mar 09 16:48:59 volumio-eddy volumio[1285]: ,establishing connection Mar 09 16:48:59 volumio-eddy volumio[1285]: error: updateQueue error: null Mar 09 16:49:01 volumio-eddy volumio[1285]: info: go-librespot daemon successfully initialized Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="obtained new client token: AADoQ20/v7bBNX+Zoit0YL6O4RsYPjxtL6AYQ0iV7WlSq34d42QXikY9Brq+pkIrxh9xSV5x+ufEYP5+xxbcirij0DuKeBLVdh0lmnPZG4jHOHEDSWyEcJajdRD3ey5L/GiyPU9KwD5kHCXlKv9NHGg+7jDeOenQzyaFFxjt2oxN7PpDL/rxt+0ZLIDHz9VvqRL94DIETSyXsJ+5wjMVvwrtTwpdYOtMbgNmZNTfpxAH3HReCTxXDwmvu30=" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=info msg="connected to ap-gew4.spotify.com:4070" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="completed keyexchange" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="completed challenge" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="authenticated as 31gydf5ifzpqbzxuacce3z7my3sa" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="authenticated as 31gydf5ifzpqbzxuacce3z7my3sa" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="dealer connection opened" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=info msg="accepted zeroconf user 31gydf5ifzpqbzxuacce3z7my3sa from A53 van Karin" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="autoplay enabled: false" Mar 09 16:49:02 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:02Z" level=debug msg="received connection id: ZmNmYjg2NjktZmRkMC00MDYwLTg1MzQtMzc0OTJlNWNhNTQ0K2RlYWxlcit0Y3A6Ly8wYWNhNTg5OC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMzIxMjg3NTREQjYwMUM5RTQwMEQ3NEI0RkY2QjA3OUMxMzYwRjQ3RTY5RDQ4OTE0NEEzNTI3NzZFMjQzQTAyNg==" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="put connect state because NEW_DEVICE" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="handling transfer player command from 4b895b5d7ea4329a5730da91b53f315995e43e81" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="resolved context of track" uri="spotify:album:49kVZFZguyqvfxt0HklIhg" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=trace msg="fetched new page 0 with 15 items (list: 15)" uri="spotify:album:49kVZFZguyqvfxt0HklIhg" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="loading track (paused: true, position: 75206ms)" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=trace msg="emitting websocket event: will_play" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="selected format OGG_VORBIS_320 (9571e5314268ddf403147fe78c5a8a0cb266b614)" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="requested aes key for file 9571e5314268ddf403147fe78c5a8a0cb266b614, gid: 3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1371" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="fetched first chunk of 14, total size is 7084983 bytes" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1132" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="fetched chunk 8/13, size: 524288" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="fetched chunk 7/13, size: 524288" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=trace msg="seek to 75206ms (diff: 80ms, samples: 3316584, bytes: 3093822)" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=debug msg="created new output device" Mar 09 16:49:03 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:03Z" level=info msg="loaded track \"Koude Kermis\" (paused: true, position: 75206ms, duration: 169744ms, prefetched: false)" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=trace msg="emitting websocket event: metadata" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=trace msg="emitting websocket event: active" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="sending successful reply for dealer request" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=trace msg="emitting websocket event: paused" Mar 09 16:49:04 volumio-eddy volumio[1285]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: volumiokiosk-touch Engine version: 3 Transport: polling Total Clients: 3 Mar 09 16:49:04 volumio-eddy volumio[1285]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 09 16:49:04 volumio-eddy volumio[1285]: info: Initializing connection to go-librespot Websocket Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="new websocket client" Mar 09 16:49:04 volumio-eddy volumio[1285]: info: Connection to go-librespot Websocket established Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="handling resume player command from 4b895b5d7ea4329a5730da91b53f315995e43e81" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=trace msg="seek to 75206ms (diff: 80ms, samples: 3316584, bytes: 3093822)" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="resume track at 75126ms" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=trace msg="scheduling prefetch in 65s" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="sending successful reply for dealer request" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 09 16:49:04 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:04Z" level=trace msg="emitting websocket event: playing" Mar 09 16:49:05 volumio-eddy volumio[1285]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3hOnzwRWRiv9SbLKeklZDc","play_origin":"playlist"}} Mar 09 16:49:05 volumio-eddy volumio[1285]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 09 16:49:05 volumio-eddy volumio[1285]: TypeError: Cannot read property 'service' of undefined Mar 09 16:49:05 volumio-eddy volumio[1285]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Mar 09 16:49:05 volumio-eddy volumio[1285]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Mar 09 16:49:05 volumio-eddy volumio[1285]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Mar 09 16:49:05 volumio-eddy volumio[1285]: at WebSocket.emit (events.js:400:28) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Receiver.emit (events.js:400:28) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 09 16:49:05 volumio-eddy volumio[1285]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 09 16:49:05 volumio-eddy volumio[1285]: at Socket.emit (events.js:400:28) Mar 09 16:49:05 volumio-eddy volumio[1285]: at addChunk (internal/streams/readable.js:293:12) Mar 09 16:49:05 volumio-eddy volumio[1285]: at readableAddChunk (internal/streams/readable.js:267:9) Mar 09 16:49:05 volumio-eddy volumio[1285]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 09 16:49:05 volumio-eddy sudo[1939]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 09 16:49:05 volumio-eddy sudo[1941]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 09 16:49:05 volumio-eddy sudo[1941]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:49:05 volumio-eddy sudo[1939]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:49:05 volumio-eddy sudo[1939]: pam_unix(sudo:session): session closed for user root Mar 09 16:49:05 volumio-eddy sudo[1941]: pam_unix(sudo:session): session closed for user root Mar 09 16:49:05 volumio-eddy sudo[1967]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-09 16:48 Mar 09 16:49:05 volumio-eddy sudo[1967]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 09 16:49:05 volumio-eddy go-librespot[1726]: time="2025-03-09T16:49:05Z" level=debug msg="fetched chunk 9/13, size: 524288" uri="spotify:track:3hOnzwRWRiv9SbLKeklZDc" PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 07:11:38 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="tinkerboard" VOLUMIO_DEVICENAME="Asus Tinkerboard" VOLUMIO_HASH="932fc3546f7cc8faa2b4d349036752dd"