-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Fri 2026-03-27 18:21:55 CET. -- Mar 27 18:21:30 volumiopeter iwconfig[1159]: Error for wireless request "Set Power Management" (8B2C) : Mar 27 18:21:30 volumiopeter iwconfig[1159]: SET failed on device wlan0 ; Operation not permitted. Mar 27 18:21:30 volumiopeter systemd-timedated[1139]: Changed local time to Fri Mar 27 18:21:30 2026 Mar 27 18:21:30 volumiopeter systemd[1]: Started Wireless Services. Mar 27 18:21:30 volumiopeter systemd[1]: ntp.service: Succeeded. Mar 27 18:21:30 volumiopeter systemd[1]: Stopped Network Time Service. Mar 27 18:21:30 volumiopeter sudo[1105]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:30 volumiopeter systemd[1]: Starting Daily apt download activities... Mar 27 18:21:30 volumiopeter systemd[1]: Starting Network Time Service... Mar 27 18:21:30 volumiopeter systemd[1]: Starting Daily man-db regeneration... Mar 27 18:21:30 volumiopeter systemd[1]: Started Volumio Backend Module. Mar 27 18:21:30 volumiopeter systemd[1]: Started Volumio Cpu Tweaker. Mar 27 18:21:30 volumiopeter systemd[1]: Started Start Volumio Kiosk. Mar 27 18:21:30 volumiopeter volumio-time-update[573]: volumio-time-update-util: System time updated successfully. Mar 27 18:21:30 volumiopeter systemd[1]: Started Volumio Time Update Utility. Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: Starting Volumio Kiosk with arguments for cursor display Mar 27 18:21:30 volumiopeter ntpd[1164]: ntpd 4.2.8p12@1.3728-o (1): Starting Mar 27 18:21:30 volumiopeter ntpd[1164]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Mar 27 18:21:30 volumiopeter systemd[1]: Started Network Time Service. Mar 27 18:21:30 volumiopeter ntpd[1188]: proto: precision = 0.583 usec (-21) Mar 27 18:21:30 volumiopeter ntpd[1188]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Mar 27 18:21:30 volumiopeter volumio-cpu-tweak[1169]: Setting RT Priority for mpd Mar 27 18:21:30 volumiopeter ntpd[1188]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Mar 27 18:21:30 volumiopeter ntpd[1188]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 1186 days ago Mar 27 18:21:30 volumiopeter ntpd[1188]: Listen and drop on 0 v6wildcard [::]:123 Mar 27 18:21:30 volumiopeter ntpd[1188]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Mar 27 18:21:30 volumiopeter ntpd[1188]: Listen normally on 2 lo 127.0.0.1:123 Mar 27 18:21:30 volumiopeter sh[492]: forked to background, child pid 1190 Mar 27 18:21:30 volumiopeter ntpd[1188]: Listen normally on 3 eth0 192.168.100.182:123 Mar 27 18:21:30 volumiopeter ntpd[1188]: Listen normally on 4 wlan0 192.168.100.211:123 Mar 27 18:21:30 volumiopeter ntpd[1188]: Listening on routing socket on fd #21 for interface updates Mar 27 18:21:30 volumiopeter ntpd[1188]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Mar 27 18:21:30 volumiopeter ntpd[1188]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Mar 27 18:21:30 volumiopeter dhcpcd[541]: forked to background, child pid 1190 Mar 27 18:21:30 volumiopeter volumio-cpu-tweak[1169]: pid 35's current scheduling policy: SCHED_OTHER Mar 27 18:21:30 volumiopeter volumio-cpu-tweak[1169]: pid 35's current scheduling priority: 0 Mar 27 18:21:30 volumiopeter volumio-cpu-tweak[1169]: Setting MPD Affinity Mar 27 18:21:30 volumiopeter volumio-cpu-tweak[1169]: pid 3's current affinity mask: 1 Mar 27 18:21:30 volumiopeter volumio-cpu-tweak[1169]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Mar 27 18:21:30 volumiopeter volumio-cpu-tweak[1169]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Mar 27 18:21:30 volumiopeter systemd[1]: volumio_cpu_tweak.service: Succeeded. Mar 27 18:21:30 volumiopeter ifplugd(eth0)[784]: client: ifup: interface eth0 already configured Mar 27 18:21:30 volumiopeter sh[492]: eth0=eth0 Mar 27 18:21:30 volumiopeter systemd[1]: man-db.service: Succeeded. Mar 27 18:21:30 volumiopeter systemd[1]: Started Daily man-db regeneration. Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: X.Org X Server 1.20.4 Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: X Protocol Version 11, Revision 0 Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: Build Operating System: Linux 4.19.0-18-armmp-lpae armv7l Debian Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: Current Operating System: Linux volumiopeter 4.4.71+ #23 SMP Sun Sep 20 12:23:26 CEST 2020 armv7l Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: 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=ac0fd7fe-5a4b-4630-8152-cff79f22b3ab uuidconfig=/extlinux/extlinux.conf vt.global_cursor_default=0 bootdelay=5 uboot_version=2017.07-g879646d1d6 root=/dev/mmcblk1p2 Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: Build Date: 18 December 2021 09:05:36AM Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: xorg-server 2:1.20.4-1+deb10u4 (https://www.debian.org/support) Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: Current version of pixman: 0.36.0 Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: Before reporting problems, check http://wiki.x.org Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: to make sure that you have the latest version. Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: Markers: (--) probed, (**) from config file, (==) default setting, Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: (++) from command line, (!!) notice, (II) informational, Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: (==) Log file: "/var/log/Xorg.0.log", Time: Fri Mar 27 18:21:30 2026 Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Mar 27 18:21:30 volumiopeter ifplugd(eth0)[784]: Program executed successfully. Mar 27 18:21:30 volumiopeter ifplugd[748]: Network Interface Plugging Daemon...start eth0...done. Mar 27 18:21:30 volumiopeter systemd[1]: Started LSB: Brings up/down network automatically. Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: gbm: failed to open any driver (search paths /usr/lib/arm-linux-gnueabihf/dri:\$${ORIGIN}/dri:/usr/lib/dri) Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: gbm: Last dlopen error: /usr/lib/dri/rockchip_dri.so: cannot open shared object file: No such file or directory Mar 27 18:21:30 volumiopeter startkiosk.sh[1173]: failed to load driver: rockchip Mar 27 18:21:31 volumiopeter ntpd[1188]: Soliciting pool server 193.25.222.136 Mar 27 18:21:31 volumiopeter nmbd[760]: [2026/03/27 18:21:31.197103, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 27 18:21:31 volumiopeter systemd[1]: Started Samba NMB Daemon. Mar 27 18:21:31 volumiopeter nmbd[760]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Mar 27 18:21:31 volumiopeter systemd[1]: Starting Samba Winbind Daemon... Mar 27 18:21:31 volumiopeter kernel: nf_conntrack: automatic helper assignment is deprecated and it will be removed soon. Use the iptables CT target to attach helpers instead. Mar 27 18:21:31 volumiopeter nmbd[760]: [2026/03/27 18:21:31.219309, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Mar 27 18:21:31 volumiopeter nmbd[760]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.100.182 for name WORKGROUP<1d>. Mar 27 18:21:31 volumiopeter nmbd[760]: This response was from IP 192.168.100.247, reporting an IP address of 192.168.100.247. Mar 27 18:21:31 volumiopeter nmbd[760]: [2026/03/27 18:21:31.219587, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Mar 27 18:21:31 volumiopeter nmbd[760]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.100.211 for name WORKGROUP<1d>. Mar 27 18:21:31 volumiopeter nmbd[760]: This response was from IP 192.168.100.247, reporting an IP address of 192.168.100.247. Mar 27 18:21:31 volumiopeter startkiosk.sh[1173]: (II) modeset(0): Initializing kms color map for depth 24, 8 bpc. Mar 27 18:21:31 volumiopeter winbindd[1268]: [2026/03/27 18:21:31.501287, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Mar 27 18:21:31 volumiopeter winbindd[1268]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 27 18:21:31 volumiopeter winbindd[1268]: [2026/03/27 18:21:31.512033, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 27 18:21:31 volumiopeter systemd[1]: Started Samba Winbind Daemon. Mar 27 18:21:31 volumiopeter winbindd[1268]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Mar 27 18:21:31 volumiopeter systemd[1]: Starting Samba SMB Daemon... Mar 27 18:21:31 volumiopeter systemd[1]: apt-daily.service: Succeeded. Mar 27 18:21:31 volumiopeter systemd[1]: Started Daily apt download activities. Mar 27 18:21:31 volumiopeter systemd[1]: Starting Daily apt upgrade and clean activities... Mar 27 18:21:31 volumiopeter smbd[1304]: [2026/03/27 18:21:31.974100, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 27 18:21:31 volumiopeter smbd[1304]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Mar 27 18:21:31 volumiopeter systemd[1]: Started Samba SMB Daemon. Mar 27 18:21:31 volumiopeter systemd[1]: Reached target Multi-User System. Mar 27 18:21:31 volumiopeter systemd[1]: Reached target Graphical Interface. Mar 27 18:21:31 volumiopeter systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 27 18:21:32 volumiopeter systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 27 18:21:32 volumiopeter systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 27 18:21:32 volumiopeter ntpd[1188]: Soliciting pool server 193.70.94.182 Mar 27 18:21:32 volumiopeter ntpd[1188]: Soliciting pool server 162.159.200.123 Mar 27 18:21:32 volumiopeter volumio[1167]: info: ------------------------------------------- Mar 27 18:21:32 volumiopeter volumio[1167]: info: ----- Volumio3 ---- Mar 27 18:21:32 volumiopeter volumio[1167]: info: ------------------------------------------- Mar 27 18:21:32 volumiopeter volumio[1167]: info: ----- System startup ---- Mar 27 18:21:32 volumiopeter volumio[1167]: info: ------------------------------------------- Mar 27 18:21:32 volumiopeter systemd[1]: apt-daily-upgrade.service: Succeeded. Mar 27 18:21:32 volumiopeter systemd[1]: Started Daily apt upgrade and clean activities. Mar 27 18:21:32 volumiopeter systemd[1]: Startup finished in 14.532s (kernel) + 15.385s (userspace) = 29.918s. Mar 27 18:21:33 volumiopeter volumio-remote-updater[578]: [2026-03-27 18:21:33] [connect] Successful connection Mar 27 18:21:33 volumiopeter ntpd[1188]: Soliciting pool server 89.161.47.132 Mar 27 18:21:33 volumiopeter ntpd[1188]: Soliciting pool server 194.92.94.32 Mar 27 18:21:33 volumiopeter ntpd[1188]: Soliciting pool server 91.210.128.220 Mar 27 18:21:33 volumiopeter volumio[1167]: info: MYVOLUMIO Environment detected Mar 27 18:21:33 volumiopeter volumio[1167]: info: Plugin folders cleanup Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning into folder /volumio/app/plugins/ Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning category audio_interface Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning category miscellanea Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning category music_service Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning category plugins.json Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning category system_controller Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning category user_interface Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning into folder /data/plugins/ Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning category audio_interface Mar 27 18:21:33 volumiopeter volumio[1167]: info: Scanning category music_service Mar 27 18:21:33 volumiopeter volumio[1167]: info: Plugin folders cleanup completed Mar 27 18:21:33 volumiopeter volumio[1167]: info: ------------------------------------------- Mar 27 18:21:33 volumiopeter volumio[1167]: info: ----- Core plugins startup ---- Mar 27 18:21:33 volumiopeter volumio[1167]: info: ------------------------------------------- Mar 27 18:21:33 volumiopeter volumio[1167]: info: Loading plugins from folder /volumio/app/plugins/ Mar 27 18:21:33 volumiopeter volumio[1167]: info: Adding plugin upnp to MyMusic Plugins Mar 27 18:21:33 volumiopeter volumio[1167]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 27 18:21:33 volumiopeter volumio[1167]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 27 18:21:33 volumiopeter volumio[1167]: info: Loading plugins from folder /data/plugins/ Mar 27 18:21:33 volumiopeter volumio[1167]: info: Loading plugin "system"... Mar 27 18:21:33 volumiopeter volumio[1167]: info: Loading plugin "appearance"... Mar 27 18:21:34 volumiopeter ntpd[1188]: Soliciting pool server 51.38.131.245 Mar 27 18:21:34 volumiopeter ntpd[1188]: Soliciting pool server 46.175.224.7 Mar 27 18:21:34 volumiopeter ntpd[1188]: Soliciting pool server 46.174.178.150 Mar 27 18:21:34 volumiopeter ntpd[1188]: Soliciting pool server 212.132.97.26 Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "network"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Refreshing Cached IP Addresses Mar 27 18:21:34 volumiopeter sudo[1428]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 18:21:34 volumiopeter sudo[1430]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "services"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "volumio5onboarding"... Mar 27 18:21:34 volumiopeter sudo[1428]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:34 volumiopeter sudo[1430]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:34 volumiopeter sudo[1428]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:34 volumiopeter sudo[1437]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 27 18:21:34 volumiopeter sudo[1430]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "alsa_controller"... Mar 27 18:21:34 volumiopeter sudo[1437]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:34 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "wizard"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "networkfs"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Starting Udev Watcher for removable devices Mar 27 18:21:34 volumiopeter volumio[1167]: info: Ignoring mount for partition: BOOT Mar 27 18:21:34 volumiopeter volumio[1167]: info: Ignoring mount for partition: volumio Mar 27 18:21:34 volumiopeter volumio[1167]: info: Ignoring mount for partition: volumio_data Mar 27 18:21:34 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "volumio_command_line_client"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Plugin upnp is not enabled Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "my_music"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "mpd"... Mar 27 18:21:34 volumiopeter sudo[1437]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:34 volumiopeter volumio[1167]: info: Plugin upnp_browser is not enabled Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "alarm-clock"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "airplay_emulation"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Starting Shairport Sync Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "last_100"... Mar 27 18:21:34 volumiopeter volumio[1167]: info: Loading plugin "webradio"... Mar 27 18:21:35 volumiopeter volumio[1167]: info: Loading plugin "i2s_dacs"... Mar 27 18:21:35 volumiopeter volumio[1167]: info: I2S DAC not set, start Auto-detection Mar 27 18:21:35 volumiopeter volumio[1167]: info: Loading plugin "volumiodiscovery"... Mar 27 18:21:35 volumiopeter ntpd[1188]: Soliciting pool server 156.17.245.123 Mar 27 18:21:35 volumiopeter ntpd[1188]: Soliciting pool server 94.154.96.7 Mar 27 18:21:35 volumiopeter ntpd[1188]: Soliciting pool server 89.161.47.131 Mar 27 18:21:35 volumiopeter volumio[1167]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 27 18:21:35 volumiopeter node[1167]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 27 18:21:35 volumiopeter node[1167]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 18:21:35 volumiopeter volumio[1167]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 18:21:35 volumiopeter volumio[1167]: *** WARNING *** For more information see Mar 27 18:21:35 volumiopeter volumio[1167]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 27 18:21:35 volumiopeter volumio[1167]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 18:21:35 volumiopeter volumio[1167]: *** WARNING *** For more information see Mar 27 18:21:35 volumiopeter node[1167]: *** WARNING *** For more information see Mar 27 18:21:35 volumiopeter node[1167]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 27 18:21:35 volumiopeter node[1167]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 18:21:35 volumiopeter node[1167]: *** WARNING *** For more information see Mar 27 18:21:35 volumiopeter volumio[1167]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 27 18:21:35 volumiopeter volumio[1167]: info: Discovery: Started advertising with name: Volumiopeter Mar 27 18:21:35 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 27 18:21:35 volumiopeter volumio[1167]: info: Loading plugin "spop"... Mar 27 18:21:35 volumiopeter volumio[1167]: info: Loading plugin "ytcr"... Mar 27 18:21:36 volumiopeter ntpd[1188]: Soliciting pool server 91.212.242.20 Mar 27 18:21:37 volumiopeter ntpd[1188]: Soliciting pool server 51.68.141.5 Mar 27 18:21:38 volumiopeter ntpd[1188]: receive: Unexpected origin timestamp 0xed713b22.1810d509 does not match aorg 0000000000.00000000 from server@94.154.96.7 xmt 0xed713b22.c12bdaa2 Mar 27 18:21:38 volumiopeter ntpd[1188]: receive: Unexpected origin timestamp 0xed713b22.18162a82 does not match aorg 0000000000.00000000 from server@194.92.94.32 xmt 0xed713b22.c1314b80 Mar 27 18:21:38 volumiopeter ntpd[1188]: receive: Unexpected origin timestamp 0xed713b22.181506ec does not match aorg 0000000000.00000000 from server@91.210.128.220 xmt 0xed713b22.c13af172 Mar 27 18:21:38 volumiopeter ntpd[1188]: receive: Unexpected origin timestamp 0xed713b22.181299f7 does not match aorg 0000000000.00000000 from server@46.174.178.150 xmt 0xed713b22.c13a6a64 Mar 27 18:21:38 volumiopeter ntpd[1188]: receive: Unexpected origin timestamp 0xed713b22.1813dbd5 does not match aorg 0000000000.00000000 from server@89.161.47.132 xmt 0xed713b22.cfa15042 Mar 27 18:21:38 volumiopeter ntpd[1188]: receive: Unexpected origin timestamp 0xed713b22.180b5ffe does not match aorg 0000000000.00000000 from server@89.161.47.131 xmt 0xed713b22.cfdf3b63 Mar 27 18:21:40 volumiopeter volumio[1167]: info: Loading plugin "ytmusic"... Mar 27 18:21:43 volumiopeter volumio[1167]: info: Loading plugin "outputs"... Mar 27 18:21:43 volumiopeter volumio[1167]: info: Loading plugin "albumart"... Mar 27 18:21:43 volumiopeter volumio[1167]: info: Plugin example_plugin is not enabled Mar 27 18:21:43 volumiopeter volumio[1167]: info: Loading plugin "inputs"... Mar 27 18:21:43 volumiopeter volumio[1167]: info: Loading plugin "updater_comm"... Mar 27 18:21:43 volumiopeter volumio[1167]: info: Plugin mpdemulation is not enabled Mar 27 18:21:43 volumiopeter volumio[1167]: info: Loading plugin "rest_api"... Mar 27 18:21:43 volumiopeter volumio[1167]: info: Loading plugin "websocket"... Mar 27 18:21:43 volumiopeter volumio[1167]: info: Starting Socket.io Server version 2.3.0 Mar 27 18:21:43 volumiopeter volumio[1167]: info: Loading plugin "fusiondsp"... Mar 27 18:21:43 volumiopeter volumio[1167]: Forking 3 albumart workers Mar 27 18:21:44 volumiopeter volumio[1167]: info: Applying required configuration parameters for plugin fusiondsp Mar 27 18:21:44 volumiopeter volumio[1167]: info: Loading plugin "nowyswiat"... Mar 27 18:21:44 volumiopeter volumio[1167]: info: Applying required configuration parameters for plugin nowyswiat Mar 27 18:21:44 volumiopeter volumio[1167]: info: [1774632104512] [RadioNowySwiat] API delay: 5 Mar 27 18:21:44 volumiopeter volumio[1167]: info: [1774632104512] [RadioNowySwiat] Stream 256Kb: http://stream.rcs.revma.com/ypqt40u0x1zuv Mar 27 18:21:44 volumiopeter volumio[1167]: info: Loading plugin "rad357pl"... Mar 27 18:21:44 volumiopeter volumio[1167]: Starting albumart workers Mar 27 18:21:44 volumiopeter volumio[1167]: Starting albumart workers Mar 27 18:21:44 volumiopeter volumio[1167]: Starting albumart workers Mar 27 18:21:44 volumiopeter volumio[1167]: info: Applying required configuration parameters for plugin rad357pl Mar 27 18:21:44 volumiopeter volumio[1167]: info: [1774632104937] [rad357pl] API delay: 5 Mar 27 18:21:44 volumiopeter volumio[1167]: info: Loading i18n strings for locale pl Mar 27 18:21:45 volumiopeter volumio[1167]: Updating browse sources language Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::initPlayerControls Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: Express server listening on port 3000 Mar 27 18:21:45 volumiopeter volumio[1167]: [Metrics] WebUI: 13s 60.35ms Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreStateMachine::resetVolumioState Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreStateMachine::getcurrentVolume Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioRetrievevolume Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreStateMachine::pushState Mar 27 18:21:45 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioPushState Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Mar 27 18:21:45 volumiopeter volumio[1167]: info: Completed loading Core Plugins Mar 27 18:21:45 volumiopeter volumio[1167]: info: Preparing to generate the ALSA configuration file Mar 27 18:21:45 volumiopeter volumio[1167]: info: Volumio Network Manager: Network status updated: 3 Mar 27 18:21:45 volumiopeter volumio[1167]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 27 18:21:45 volumiopeter volumio[1167]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 27 18:21:45 volumiopeter volumio[1167]: info: Reading ALSA contributions from plugins. Mar 27 18:21:45 volumiopeter volumio[1167]: info: Reloading queue from file Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreStateMachine::setRepeat null single undefined Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreStateMachine::pushState Mar 27 18:21:45 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioPushState Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreStateMachine::setRandom true Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreStateMachine::pushState Mar 27 18:21:45 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioPushState Mar 27 18:21:45 volumiopeter volumio[1167]: info: Setting Device type: Tinkerboard Mar 27 18:21:45 volumiopeter volumio[1167]: info: Asound.conf file unchanged, so no further update is needed Mar 27 18:21:45 volumiopeter volumio[1167]: info: Output device has changed, restarting MPD Mar 27 18:21:45 volumiopeter volumio[1167]: info: Output device has changed, restarting Shairport Sync Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:45 volumiopeter sudo[1719]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 27 18:21:45 volumiopeter sudo[1721]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 27 18:21:45 volumiopeter sudo[1719]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:45 volumiopeter sudo[1721]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:45 volumiopeter sudo[1719]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:45 volumiopeter volumio[1167]: info: ___________ START PLUGINS ___________ Mar 27 18:21:45 volumiopeter systemd[1]: Listening on mpd.socket. Mar 27 18:21:45 volumiopeter systemd[1]: Starting Music Player Daemon... Mar 27 18:21:45 volumiopeter volumio[1167]: info: ControllerMpd::onStart: Initializing MPD Mar 27 18:21:45 volumiopeter volumio[1167]: info: Creating MPD Configuration file Mar 27 18:21:45 volumiopeter sudo[1741]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 27 18:21:45 volumiopeter sudo[1741]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:45 volumiopeter sudo[1744]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:45 volumiopeter sudo[1752]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 27 18:21:45 volumiopeter systemd[1]: Started Volumio5 Onboarding Server. Mar 27 18:21:45 volumiopeter sudo[1741]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:45 volumiopeter sudo[1744]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:45 volumiopeter sudo[1744]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:45 volumiopeter sudo[1752]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:45 volumiopeter sudo[1739]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 27 18:21:45 volumiopeter sudo[1739]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:45 volumiopeter sudo[1739]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 18:21:45 volumiopeter volumio[1167]: info: [1774632105913] CoreMusicLibrary::Adding element Last_100 Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 18:21:45 volumiopeter volumio[1167]: info: [1774632105917] CoreMusicLibrary::Adding element Webradio Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:45 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 18:21:45 volumiopeter volumio[1167]: info: Initializing BBC Radios Mar 27 18:21:45 volumiopeter systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Mar 27 18:21:45 volumiopeter systemd[1]: mpd.service: Succeeded. Mar 27 18:21:45 volumiopeter systemd[1]: Stopped Music Player Daemon. Mar 27 18:21:45 volumiopeter systemd[1]: Starting Music Player Daemon... Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: Creating Spotify config file Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter sudo[1793]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 27 18:21:46 volumiopeter sudo[1793]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:46 volumiopeter sudo[1793]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Mar 27 18:21:46 volumiopeter sudo[1793]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:46 volumiopeter volumio5-onboarding[1758]: time=2026-03-27T18:21:46.150+01:00 level=INFO msg="running volumio5-device-gateway" version=687ad144+CHANGES buildDate=2026-02-10T16:50:24Z Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 18:21:46 volumiopeter volumio[1167]: info: [1774632106164] CoreMusicLibrary::Adding element YouTube Music Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:46 volumiopeter volumio[1167]: Cannot find translation for source YouTube Music Mar 27 18:21:46 volumiopeter volumio[1167]: info: Loading i18n strings for locale pl Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: FusionDsp - mixtype--------------------- None Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 18:21:46 volumiopeter volumio[1167]: info: [1774632106183] CoreMusicLibrary::Adding element Radio Nowy Swiat Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:46 volumiopeter volumio[1167]: Cannot find translation for source YouTube Music Mar 27 18:21:46 volumiopeter volumio[1167]: Cannot find translation for source Radio Nowy Swiat Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 18:21:46 volumiopeter volumio[1167]: info: [1774632106189] CoreMusicLibrary::Adding element RADIO 357 Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:46 volumiopeter volumio[1167]: Cannot find translation for source YouTube Music Mar 27 18:21:46 volumiopeter volumio[1167]: Cannot find translation for source Radio Nowy Swiat Mar 27 18:21:46 volumiopeter volumio[1167]: Cannot find translation for source RADIO 357 Mar 27 18:21:46 volumiopeter volumio[1167]: info: Volumio Calling Home Mar 27 18:21:46 volumiopeter volumio[1167]: info: Preparing to generate the ALSA configuration file Mar 27 18:21:46 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] Setting app pid to stored value: 52955542-bdbb-44ea-bb32-5ee08d616e0a Mar 27 18:21:46 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] Starting YouTubeApp... Mar 27 18:21:46 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube) Configuring session with stored MDX context: Mar 27 18:21:46 volumiopeter volumio[1167]: { Mar 27 18:21:46 volumiopeter volumio[1167]: deviceId: '2866843e-0e79-4981-a0e6-e8281f2aa3e1', Mar 27 18:21:46 volumiopeter volumio[1167]: screenId: '2bb12kuqsdpq3o2srmuee2v06h' Mar 27 18:21:46 volumiopeter volumio[1167]: } Mar 27 18:21:46 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube Music) Configuring session with stored MDX context: Mar 27 18:21:46 volumiopeter volumio[1167]: { Mar 27 18:21:46 volumiopeter volumio[1167]: deviceId: 'a9448faa-3d1d-4c62-8d3d-a9a39535b691', Mar 27 18:21:46 volumiopeter volumio[1167]: screenId: 'ievt6flovh96l6hfco7c0s9qbk' Mar 27 18:21:46 volumiopeter volumio[1167]: } Mar 27 18:21:46 volumiopeter volumio[1167]: info: Discovery: adding 9deeb9af-7671-4936-ae1c-22dda9d1abce Mar 27 18:21:46 volumiopeter volumio[1167]: info: Discovery: Found device Volumiopeter Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:46 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:46 volumiopeter volumio[1167]: info: Discovery: this is already registered, 9deeb9af-7671-4936-ae1c-22dda9d1abce Mar 27 18:21:46 volumiopeter volumio[1167]: info: Discovery: Found device Volumiopeter Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:46 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:46 volumiopeter volumio[1167]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 27 18:21:46 volumiopeter volumio[1167]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 27 18:21:46 volumiopeter volumio[1167]: info: Reading ALSA contributions from plugins. Mar 27 18:21:46 volumiopeter volumio[1167]: info: MPD Permissions set Mar 27 18:21:46 volumiopeter volumio[1167]: info: MPD Permissions set Mar 27 18:21:46 volumiopeter volumio[1167]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 27 18:21:46 volumiopeter volumio[1167]: info: Spotify config file written Mar 27 18:21:46 volumiopeter volumio[1167]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 27 18:21:46 volumiopeter volumio[1167]: info: Received Get System Info Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 18:21:46 volumiopeter volumio[1167]: info: Discovery: Getting this device information Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:46 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 18:21:46 volumiopeter volumio5-onboarding[1758]: time=2026-03-27T18:21:46.414+01:00 level=INFO msg="system info for c1795d5b9cf6aa78f0a0d7a7925d5952" deviceName=Volumiopeter deviceVariant=volumio deviceModel= softwareVersion=3.912 Mar 27 18:21:46 volumiopeter sudo[1814]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 18:21:46 volumiopeter volumio[1167]: 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 27 18:21:46 volumiopeter volumio[1167]: info: Volumio called home Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter sudo[1814]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Mar 27 18:21:46 volumiopeter systemd[1]: Started go-librespot Daemon. Mar 27 18:21:46 volumiopeter go-librespot[1825]: go-librespot daemon starting... Mar 27 18:21:46 volumiopeter sudo[1814]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:46 volumiopeter volumio[1167]: info: No need to fix Spotify hosts Mar 27 18:21:46 volumiopeter volumio[1167]: info: Received Get System Info Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 18:21:46 volumiopeter volumio[1167]: info: Discovery: Getting this device information Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:46 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 18:21:46 volumiopeter volumio5-onboarding[1758]: time=2026-03-27T18:21:46.618+01:00 level=INFO msg="enabling local network discovery" Mar 27 18:21:46 volumiopeter volumio5-onboarding[1758]: time=2026-03-27T18:21:46.619+01:00 level=INFO msg="enabling BLE discovery" Mar 27 18:21:46 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:46+01:00" level=info msg="running go-librespot 0.4.0" Mar 27 18:21:46 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:46+01:00" level=debug msg="app state loaded" Mar 27 18:21:46 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:46+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 18:21:46 volumiopeter volumio[1167]: info: Starting Shairport Sync Mar 27 18:21:46 volumiopeter volumio[1167]: info: Starting Shairport Sync Mar 27 18:21:46 volumiopeter volumio[1167]: info: Starting Shairport Sync Mar 27 18:21:46 volumiopeter sudo[1844]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 18:21:46 volumiopeter sudo[1850]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 18:21:46 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:46 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:46 volumiopeter sudo[1847]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 18:21:46 volumiopeter sudo[1850]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:46 volumiopeter sudo[1844]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:46 volumiopeter systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 27 18:21:46 volumiopeter systemd[1]: shairport-sync.service: Succeeded. Mar 27 18:21:46 volumiopeter systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 27 18:21:46 volumiopeter systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 27 18:21:46 volumiopeter bluetoothd[618]: src/adapter.c:store_adapter_info() Unable set contents for /usr/var/lib/bluetooth/70:66:55:76:4E:18/settings: (Failed to create file “/usr/var/lib/bluetooth/70:66:55:76:4E:18/settings.7TE1M3”: No such file or directory) Mar 27 18:21:46 volumiopeter sudo[1850]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:46 volumiopeter volumio5-onboarding[1758]: time=2026-03-27T18:21:46.921+01:00 level=INFO msg="bootstrapping state" hasInternet=true Mar 27 18:21:46 volumiopeter sudo[1847]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:47 volumiopeter systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 27 18:21:47 volumiopeter volumio[1167]: info: Asound.conf file unchanged, so no further update is needed Mar 27 18:21:47 volumiopeter volumio[1167]: info: Output device has changed, restarting MPD Mar 27 18:21:47 volumiopeter systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Mar 27 18:21:47 volumiopeter systemd[1]: shairport-sync.service: Succeeded. Mar 27 18:21:47 volumiopeter systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 27 18:21:47 volumiopeter systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 27 18:21:47 volumiopeter sudo[1844]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:47 volumiopeter sudo[1847]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:47 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:47+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 27 18:21:47 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:47+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 27 18:21:47 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:47+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 27 18:21:47 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:47+01:00" level=info msg="zeroconf server listening on port 35203" Mar 27 18:21:47 volumiopeter sudo[1873]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 27 18:21:47 volumiopeter volumio[1167]: info: Output device has changed, restarting Shairport Sync Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:47 volumiopeter sudo[1873]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:47 volumiopeter sudo[1882]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 27 18:21:47 volumiopeter sudo[1873]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:47 volumiopeter sudo[1882]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:47 volumiopeter volumio[1167]: info: Received Get System Info Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 18:21:47 volumiopeter volumio[1167]: info: Discovery: Getting this device information Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:47 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 18:21:47 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:47+01:00" level=debug msg="obtained new client token: AAAdzJ0OEFzt9FozmWVX+cePwlMov9qYnAq5m/X6/r64Zmx42nWDBC/Ece+NM8VHzxWCp8NMdYirt+93e4/EPNqOsBdSE01SCD1jX/uMHRA+i9/tOcYiK23bZE8LSVGEXk5KbUtzc/DiekqOBQNSlDw2VL3+v4ueBmwMLVV0zPpzmNYzntePDC6S8vZ5JrVo93xUOskSbOtDW3O/mN2BgwK8lR3xcDUiTwWimMt2up4QouMCd5cW86o=" Mar 27 18:21:47 volumiopeter volumio[1167]: info: Shairport-Sync Started Mar 27 18:21:47 volumiopeter systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Mar 27 18:21:47 volumiopeter systemd[1]: mpd.service: Succeeded. Mar 27 18:21:47 volumiopeter systemd[1]: Stopped Music Player Daemon. Mar 27 18:21:47 volumiopeter volumio[1167]: Error adding Membership: Error: addMembership EINVAL Mar 27 18:21:47 volumiopeter systemd[1]: Starting Music Player Daemon... Mar 27 18:21:47 volumiopeter volumio[1167]: info: MPD Permissions set Mar 27 18:21:47 volumiopeter volumio[1167]: info: Shairport-Sync Started Mar 27 18:21:47 volumiopeter volumio[1167]: info: Shairport-Sync Started Mar 27 18:21:47 volumiopeter volumio[1167]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 27 18:21:47 volumiopeter volumio[1167]: SPOTIFY: BQCeVTN3VRASjrEFE6VGaP04ka52T5EX1nuhu941v8CMfEOo9EF-6my28qncTB15SP-S0LWCLissvgrXrUu7QXYiL0TP6ZblCHgvRa044FwUisR0NBGM0xm_B6VMaL48hlDwfvsshTNrchNVURqPVA0jDKLRjqvvzhI6BweG5PywRCXLSWliCpNoEdeW9EZzGCJnE4QrHgMgRRZqoadoDHYoeSRyFvLK1wCoOITInLL0M-j2mgLmGTdPUkYPJtjsp8wiOhn6Oum08JdBw-mmgLdc-jvhAJCw5HsVwOan3z0kWE0UXw4Cn7VYrh7pAA Mar 27 18:21:47 volumiopeter volumio[1167]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 27 18:21:47 volumiopeter volumio[1167]: info: New Spotify access token = BQCeVTN3VRASjrEFE6VGaP04ka52T5EX1nuhu941v8CMfEOo9EF-6my28qncTB15SP-S0LWCLissvgrXrUu7QXYiL0TP6ZblCHgvRa044FwUisR0NBGM0xm_B6VMaL48hlDwfvsshTNrchNVURqPVA0jDKLRjqvvzhI6BweG5PywRCXLSWliCpNoEdeW9EZzGCJnE4QrHgMgRRZqoadoDHYoeSRyFvLK1wCoOITInLL0M-j2mgLmGTdPUkYPJtjsp8wiOhn6Oum08JdBw-mmgLdc-jvhAJCw5HsVwOan3z0kWE0UXw4Cn7VYrh7pAA Mar 27 18:21:47 volumiopeter volumio[1167]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter sudo[1898]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 27 18:21:47 volumiopeter sudo[1898]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Mar 27 18:21:47 volumiopeter sudo[1898]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Mar 27 18:21:47 volumiopeter sudo[1898]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube Music) Obtained lounge token: Mar 27 18:21:47 volumiopeter volumio[1167]: { Mar 27 18:21:47 volumiopeter volumio[1167]: screenId: 'ievt6flovh96l6hfco7c0s9qbk', Mar 27 18:21:47 volumiopeter volumio[1167]: refreshIntervalInMillis: 1123200000, Mar 27 18:21:47 volumiopeter volumio[1167]: remoteRefreshIntervalMs: 79200000, Mar 27 18:21:47 volumiopeter volumio[1167]: refreshIntervalMs: 1123200000, Mar 27 18:21:47 volumiopeter volumio[1167]: loungeTokenLifespanMs: 1209600000, Mar 27 18:21:47 volumiopeter volumio[1167]: loungeToken: 'AGdO5p8iQUYNOJJkZSthnM-G0J0O12wqHYvou_psPR3oYRoitQCb_i6qi0BU6cH9eDSzY6LoKS-95V8dh0aTtjEcyDvwN99c2UJoJeeKVbI3unzIfiAxzK8', Mar 27 18:21:47 volumiopeter volumio[1167]: remoteRefreshIntervalInMillis: 79200000, Mar 27 18:21:47 volumiopeter volumio[1167]: expiration: 1775755306721 Mar 27 18:21:47 volumiopeter volumio[1167]: } Mar 27 18:21:47 volumiopeter volumio[1167]: info: Starting Shairport Sync Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube) Obtained lounge token: Mar 27 18:21:47 volumiopeter volumio[1167]: { Mar 27 18:21:47 volumiopeter volumio[1167]: screenId: '2bb12kuqsdpq3o2srmuee2v06h', Mar 27 18:21:47 volumiopeter volumio[1167]: refreshIntervalInMillis: 1123200000, Mar 27 18:21:47 volumiopeter volumio[1167]: remoteRefreshIntervalMs: 79200000, Mar 27 18:21:47 volumiopeter volumio[1167]: refreshIntervalMs: 1123200000, Mar 27 18:21:47 volumiopeter volumio[1167]: loungeTokenLifespanMs: 1209600000, Mar 27 18:21:47 volumiopeter volumio[1167]: loungeToken: 'AGdO5p_3DEhh0ncaBgYu_KcwyUWEvL_-eA7DIH5heSxXp3HrHP9NZ-gFke_L4SLMxb0b2V5_fXzmsT2dlGB3xMpXIW2Qavz-xAW1_IT-k5cNLrgG4U67nZs', Mar 27 18:21:47 volumiopeter volumio[1167]: remoteRefreshIntervalInMillis: 79200000, Mar 27 18:21:47 volumiopeter volumio[1167]: expiration: 1775755306688 Mar 27 18:21:47 volumiopeter volumio[1167]: } Mar 27 18:21:47 volumiopeter sudo[1915]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 18:21:47 volumiopeter sudo[1915]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:47 volumiopeter systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 27 18:21:47 volumiopeter systemd[1]: shairport-sync.service: Succeeded. Mar 27 18:21:47 volumiopeter systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 27 18:21:47 volumiopeter systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 27 18:21:47 volumiopeter sudo[1915]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:47 volumiopeter volumio[1167]: SPOTIFY: User informations: {"country":"PL","display_name":"Peter","email":"pechacinski_mail@onet.pl","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31vincoxahbjx7cusd3j6nmhcvka"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31vincoxahbjx7cusd3j6nmhcvka","id":"31vincoxahbjx7cusd3j6nmhcvka","images":[],"product":"premium","type":"user","uri":"spotify:user:31vincoxahbjx7cusd3j6nmhcvka"} Mar 27 18:21:47 volumiopeter volumio[1167]: info: Spotify Successfully logged in Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 18:21:47 volumiopeter volumio[1167]: info: [1774632107473] CoreMusicLibrary::Adding element Spotify Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:47 volumiopeter volumio[1167]: Cannot find translation for source YouTube Music Mar 27 18:21:47 volumiopeter volumio[1167]: Cannot find translation for source Radio Nowy Swiat Mar 27 18:21:47 volumiopeter volumio[1167]: Cannot find translation for source RADIO 357 Mar 27 18:21:47 volumiopeter volumio[1167]: Cannot find translation for source Spotify Mar 27 18:21:47 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:47+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 27 18:21:47 volumiopeter volumio[1167]: info: Shairport-Sync Started Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube Music) Received messages for establishing session: Mar 27 18:21:47 volumiopeter volumio[1167]: [ Mar 27 18:21:47 volumiopeter volumio[1167]: Message { AID: 0, name: 'c', payload: [ '17D6B70F37A52CB5', '', 8 ] }, Mar 27 18:21:47 volumiopeter volumio[1167]: Message { Mar 27 18:21:47 volumiopeter volumio[1167]: AID: 1, Mar 27 18:21:47 volumiopeter volumio[1167]: name: 'S', Mar 27 18:21:47 volumiopeter volumio[1167]: payload: 'J4oXoyzBkdDOgiJADcw1uNNElmzkBucq' Mar 27 18:21:47 volumiopeter volumio[1167]: }, Mar 27 18:21:47 volumiopeter volumio[1167]: Message { Mar 27 18:21:47 volumiopeter volumio[1167]: AID: 2, Mar 27 18:21:47 volumiopeter volumio[1167]: name: 'loungeStatus', Mar 27 18:21:47 volumiopeter volumio[1167]: payload: { Mar 27 18:21:47 volumiopeter volumio[1167]: queueId: 'RQGn7rfEyOhg5SZh-f56NSrtfgY-k', Mar 27 18:21:47 volumiopeter volumio[1167]: devices: '[{"app":"ytcr","capabilities":"dsp,mic,dpa,ntb","clientName":"unknown","experiments":"","name":"YouTube on Volumiopeter","theme":"m","id":"a9448faa-3d1d-4c62-8d3d-a9a39535b691","type":"LOUNGE_SCREEN","hasCc":"true","deviceInfo":"{\\"year\\":0,\\"os\\":\\"Windows\\",\\"osVersion\\":\\"10.0\\",\\"chipset\\":\\"\\",\\"clientName\\":\\"TVHTML5\\",\\"dialAdditionalDataSupportLevel\\":\\"unsupported\\",\\"mdxDialServerType\\":\\"MDX_DIAL_SERVER_TYPE_UNKNOWN\\",\\"brand\\":\\"Generic\\",\\"model\\":\\"SmartTV\\"}","receiverIdentityMatchStatus":"IS_RECEIVER"}]', Mar 27 18:21:47 volumiopeter volumio[1167]: connectionEventDetails: '{"deviceId":"a9448faa-3d1d-4c62-8d3d-a9a39535b691"}' Mar 27 18:21:47 volumiopeter volumio[1167]: } Mar 27 18:21:47 volumiopeter volumio[1167]: }, Mar 27 18:21:47 volumiopeter volumio[1167]: Message { AID: 3, name: 'getNowPlaying', payload: {} }, Mar 27 18:21:47 volumiopeter volumio[1167]: Message { AID: 4, name: 'getDiscoveryDeviceId', payload: {} } Mar 27 18:21:47 volumiopeter volumio[1167]: ] Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: ----------------------------------- Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (AID: 2) (YouTube Music) Incoming message: 'loungeStatus' Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] Connecting to RPC URL: https://www.youtube.com/api/lounge/bc/bind?AID=3&CI=0&RID=rpc&SID=17D6B70F37A52CB5&TYPE=xmlhttp&VER=8&app=ytcr&capabilities=dsp%2Cmic%2Cdpa%2Cntb&cst=m&device=LOUNGE_SCREEN&gsessionid=J4oXoyzBkdDOgiJADcw1uNNElmzkBucq&id=a9448faa-3d1d-4c62-8d3d-a9a39535b691&loungeIdToken=AGdO5p8iQUYNOJJkZSthnM-G0J0O12wqHYvou_psPR3oYRoitQCb_i6qi0BU6cH9eDSzY6LoKS-95V8dh0aTtjEcyDvwN99c2UJoJeeKVbI3unzIfiAxzK8&mdxVersion=2&name=YouTube%20on%20Volumiopeter&obfuscatedGaiaId=&t=1&theme=m&v=2&zx=c85e4be99d2b Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube) Received messages for establishing session: Mar 27 18:21:47 volumiopeter volumio[1167]: [ Mar 27 18:21:47 volumiopeter volumio[1167]: Message { AID: 0, name: 'c', payload: [ 'E5DA71D93E0C37FB', '', 8 ] }, Mar 27 18:21:47 volumiopeter volumio[1167]: Message { Mar 27 18:21:47 volumiopeter volumio[1167]: AID: 1, Mar 27 18:21:47 volumiopeter volumio[1167]: name: 'S', Mar 27 18:21:47 volumiopeter volumio[1167]: payload: 'ZskbNKHzgL3oZUG3wGhHdgwe0-77MPW7' Mar 27 18:21:47 volumiopeter volumio[1167]: }, Mar 27 18:21:47 volumiopeter volumio[1167]: Message { Mar 27 18:21:47 volumiopeter volumio[1167]: AID: 2, Mar 27 18:21:47 volumiopeter volumio[1167]: name: 'loungeStatus', Mar 27 18:21:47 volumiopeter volumio[1167]: payload: { Mar 27 18:21:47 volumiopeter volumio[1167]: queueId: 'RQz3jVJHEr9QsrqzfxzTU2JSbttmU', Mar 27 18:21:47 volumiopeter volumio[1167]: devices: '[{"app":"ytcr","capabilities":"dsp,mic,dpa,ntb,que,mus","clientName":"unknown","experiments":"","name":"YouTube on Volumiopeter","theme":"cl","id":"2866843e-0e79-4981-a0e6-e8281f2aa3e1","type":"LOUNGE_SCREEN","hasCc":"true","deviceInfo":"{\\"year\\":0,\\"os\\":\\"Windows\\",\\"osVersion\\":\\"10.0\\",\\"chipset\\":\\"\\",\\"clientName\\":\\"TVHTML5\\",\\"dialAdditionalDataSupportLevel\\":\\"unsupported\\",\\"mdxDialServerType\\":\\"MDX_DIAL_SERVER_TYPE_UNKNOWN\\",\\"brand\\":\\"Generic\\",\\"model\\":\\"SmartTV\\"}","receiverIdentityMatchStatus":"IS_RECEIVER"}]', Mar 27 18:21:47 volumiopeter volumio[1167]: connectionEventDetails: '{"deviceId":"2866843e-0e79-4981-a0e6-e8281f2aa3e1"}' Mar 27 18:21:47 volumiopeter volumio[1167]: } Mar 27 18:21:47 volumiopeter volumio[1167]: }, Mar 27 18:21:47 volumiopeter volumio[1167]: Message { AID: 3, name: 'getNowPlaying', payload: {} }, Mar 27 18:21:47 volumiopeter volumio[1167]: Message { AID: 4, name: 'getDiscoveryDeviceId', payload: {} } Mar 27 18:21:47 volumiopeter volumio[1167]: ] Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: ----------------------------------- Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (AID: 2) (YouTube) Incoming message: 'loungeStatus' Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] Connecting to RPC URL: https://www.youtube.com/api/lounge/bc/bind?AID=3&CI=0&RID=rpc&SID=E5DA71D93E0C37FB&TYPE=xmlhttp&VER=8&app=ytcr&capabilities=dsp%2Cmic%2Cdpa%2Cntb&cst=m&device=LOUNGE_SCREEN&gsessionid=ZskbNKHzgL3oZUG3wGhHdgwe0-77MPW7&id=2866843e-0e79-4981-a0e6-e8281f2aa3e1&loungeIdToken=AGdO5p_3DEhh0ncaBgYu_KcwyUWEvL_-eA7DIH5heSxXp3HrHP9NZ-gFke_L4SLMxb0b2V5_fXzmsT2dlGB3xMpXIW2Qavz-xAW1_IT-k5cNLrgG4U67nZs&mdxVersion=2&name=YouTube%20on%20Volumiopeter&obfuscatedGaiaId=&t=1&theme=cl&v=2&zx=166028491f60 Mar 27 18:21:47 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:47+01:00" level=debug msg="completed keyexchange" Mar 27 18:21:47 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:47+01:00" level=debug msg="completed challenge" Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] RPC connection established. Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube Music) Session established. Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube Music) Saving MDX context to data store: Mar 27 18:21:47 volumiopeter volumio[1167]: { Mar 27 18:21:47 volumiopeter volumio[1167]: deviceId: 'a9448faa-3d1d-4c62-8d3d-a9a39535b691', Mar 27 18:21:47 volumiopeter volumio[1167]: screenId: 'ievt6flovh96l6hfco7c0s9qbk' Mar 27 18:21:47 volumiopeter volumio[1167]: } Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: ----------------------------------- Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (AID: 4) (YouTube Music) Incoming message: 'getDiscoveryDeviceId' Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (AID: 4) (YouTube Music) Not handled: 'getDiscoveryDeviceId' Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] RPC connection established. Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube) Session established. Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (YouTube) Saving MDX context to data store: Mar 27 18:21:47 volumiopeter volumio[1167]: { Mar 27 18:21:47 volumiopeter volumio[1167]: deviceId: '2866843e-0e79-4981-a0e6-e8281f2aa3e1', Mar 27 18:21:47 volumiopeter volumio[1167]: screenId: '2bb12kuqsdpq3o2srmuee2v06h' Mar 27 18:21:47 volumiopeter volumio[1167]: } Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] Starting DIAL server... Mar 27 18:21:47 volumiopeter volumio[1167]: info: [yt-cast-receiver] DIAL server listening on port 8098 Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioRetrievevolume Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:47 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreStateMachine::pushState Mar 27 18:21:47 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:47 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioPushState Mar 27 18:21:47 volumiopeter volumio[1167]: error: [ytcr] VolumeControl failed to obtain volume from Volumio: Mar 27 18:21:47 volumiopeter volumio[1167]: (TypeError) Cannot read property 'vol' of undefined Mar 27 18:21:47 volumiopeter volumio[1167]: TypeError: Cannot read property 'vol' of undefined Mar 27 18:21:47 volumiopeter volumio[1167]: at VolumeControl.getVolume (/data/plugins/music_service/ytcr/dist/lib/VolumeControl.js:56:42) Mar 27 18:21:47 volumiopeter volumio[1167]: at processTicksAndRejections (internal/process/task_queues.js:95:5) Mar 27 18:21:47 volumiopeter volumio[1167]: at async VolumeControl.init (/data/plugins/music_service/ytcr/dist/lib/VolumeControl.js:28:68) Mar 27 18:21:47 volumiopeter volumio[1167]: at async /data/plugins/music_service/ytcr/dist/index.js:326:13 Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [ytcr] VolumeControl initialized with current volume: Mar 27 18:21:47 volumiopeter volumio[1167]: { level: 0, muted: false } Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: ----------------------------------- Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (AID: 4) (YouTube) Incoming message: 'getDiscoveryDeviceId' Mar 27 18:21:47 volumiopeter volumio[1167]: verbose: [yt-cast-receiver] (AID: 4) (YouTube) Not handled: 'getDiscoveryDeviceId' Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=info msg="authenticated AP" username="31************************ka" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=info msg="authenticated Login5" username="31************************ka" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="initializing zeroconf session" username="31************************ka" Mar 27 18:21:48 volumiopeter volumio[1167]: info: camilladsp service started and running in background, instance 1 Mar 27 18:21:48 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="dealer connection opened" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=trace msg="starting accesspoint recv loop" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=trace msg="starting dealer recv loop" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=trace msg="received accesspoint ping" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="received connection id: ZWE3N2ZmZTktYTc3...NDI0NzM3MUY0Nw==" Mar 27 18:21:48 volumiopeter volumio[1167]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 96000 176400 192000 <-AAAAAAAAAAAAA Mar 27 18:21:48 volumiopeter volumio[1167]: info: FusionDsp loaded Mar 27 18:21:48 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 18:21:48 volumiopeter volumio[1167]: info: FusionDsp - Reporting Fusion DSP Enabled Mar 27 18:21:48 volumiopeter volumio[1167]: info: Adding Signal Path Element [object Object] Mar 27 18:21:48 volumiopeter volumio[1167]: info: Adding fusiondspeq DSP Signal Path Element Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 27 18:21:48 volumiopeter volumio[1167]: info: FusionDsp - ---- installed callbackRead Mar 27 18:21:48 volumiopeter sudo[1940]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Mar 27 18:21:48 volumiopeter volumio[1167]: info: FusionDsp - File size found in array! Mar 27 18:21:48 volumiopeter volumio[1167]: info: FusionDsp - Nulleq applied Mar 27 18:21:48 volumiopeter sudo[1940]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 18:21:48 volumiopeter volumio[1167]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 27 18:21:48 volumiopeter systemd[1]: Started FusionDsp Daemon. Mar 27 18:21:48 volumiopeter sudo[1940]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="update volume requested to 65535/65535" Mar 27 18:21:48 volumiopeter volumio[1167]: info: FusionDsp - {"Reload":{"result":"Ok"}} Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=trace msg="emitting websocket event: volume" Mar 27 18:21:48 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:48+01:00" level=trace msg="received accesspoint pong ack" Mar 27 18:21:48 volumiopeter volumio-remote-updater[578]: [2026-03-27 18:21:48] [connect] Successful connection Mar 27 18:21:48 volumiopeter volumio-remote-updater[578]: [2026-03-27 18:21:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1774632108 101 Mar 27 18:21:48 volumiopeter volumio[1167]: 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: 4 Mar 27 18:21:48 volumiopeter volumio[1167]: 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: 5 Mar 27 18:21:49 volumiopeter mpd[1918]: Mar 27 18:21 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 27 18:21:49 volumiopeter systemd[1]: Started Music Player Daemon. Mar 27 18:21:49 volumiopeter sudo[1752]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:49 volumiopeter sudo[1882]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:49 volumiopeter sudo[1721]: pam_unix(sudo:session): session closed for user root Mar 27 18:21:49 volumiopeter volumio[1167]: error: MPD error: The expression evaluated to a falsy value: Mar 27 18:21:49 volumiopeter volumio[1167]: assert.ok(self.idling) Mar 27 18:21:49 volumiopeter volumio[1167]: error: The expression evaluated to a falsy value: Mar 27 18:21:49 volumiopeter volumio[1167]: assert.ok(self.idling) Mar 27 18:21:49 volumiopeter volumio[1167]: error: MPD error: The expression evaluated to a falsy value: Mar 27 18:21:49 volumiopeter volumio[1167]: assert.ok(self.idling) Mar 27 18:21:49 volumiopeter volumio[1167]: error: The expression evaluated to a falsy value: Mar 27 18:21:49 volumiopeter volumio[1167]: assert.ok(self.idling) Mar 27 18:21:49 volumiopeter volumio[1167]: info: MPD running with PID1918 Mar 27 18:21:49 volumiopeter volumio[1167]: ,establishing connection Mar 27 18:21:49 volumiopeter volumio[1167]: error: updateQueue error: null Mar 27 18:21:49 volumiopeter volumio[1167]: verbose: [ytcr] MPD connected Mar 27 18:21:49 volumiopeter volumio[1167]: verbose: [ytcr] MPDSubsystemEventEmitter enabled. Mar 27 18:21:49 volumiopeter volumio[1167]: verbose: [ytcr] Receiver started with options: Mar 27 18:21:49 volumiopeter volumio[1167]: { Mar 27 18:21:49 volumiopeter volumio[1167]: dial: { port: 8098, bindToInterfaces: undefined }, Mar 27 18:21:49 volumiopeter volumio[1167]: app: { Mar 27 18:21:49 volumiopeter volumio[1167]: enableAutoplayOnConnect: true, Mar 27 18:21:49 volumiopeter volumio[1167]: resetPlayerOnDisconnectPolicy: 'allDisconnected' Mar 27 18:21:49 volumiopeter volumio[1167]: }, Mar 27 18:21:49 volumiopeter volumio[1167]: dataStore: ReceiverDataStore {}, Mar 27 18:21:49 volumiopeter volumio[1167]: logger: Logger { level: 'debug', color: true }, Mar 27 18:21:49 volumiopeter volumio[1167]: logLevel: 'debug', Mar 27 18:21:49 volumiopeter volumio[1167]: device: { name: 'Volumiopeter' } Mar 27 18:21:49 volumiopeter volumio[1167]: } Mar 27 18:21:49 volumiopeter volumio[1167]: info: Completed starting Core Plugins Mar 27 18:21:49 volumiopeter volumio[1167]: info: ------------------------------------------- Mar 27 18:21:49 volumiopeter volumio[1167]: info: ----- MyVolumio plugins startup ---- Mar 27 18:21:49 volumiopeter volumio[1167]: info: ------------------------------------------- Mar 27 18:21:49 volumiopeter volumio[1167]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 27 18:21:49 volumiopeter volumio[1167]: error: updateQueue error: null Mar 27 18:21:49 volumiopeter systemd[1]: systemd-fsckd.service: Succeeded. Mar 27 18:21:49 volumiopeter volumio[1167]: info: go-librespot daemon successfully initialized Mar 27 18:21:50 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetVisibleSources Mar 27 18:21:50 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:50 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 27 18:21:50 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:50 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:50 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 27 18:21:50 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 18:21:50 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 18:21:50 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 27 18:21:50 volumiopeter volumio[1167]: 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: 6 Mar 27 18:21:51 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:51 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:51 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 27 18:21:51 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetVisibleSources Mar 27 18:21:51 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 18:21:51 volumiopeter volumio[1167]: info: Listing playlists Mar 27 18:21:51 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 27 18:21:51 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 18:21:51 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 18:21:51 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=debug msg="handling transfer player command from b25140ebdecffdfe1d75871383b3c91a74676b2b" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=debug msg="resolved context of track" uri="spotify:album:0KFEFxaB9cvNbNhjs0XNAv" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=trace msg="fetched new page 0 with 25 items (list: 25)" uri="spotify:album:0KFEFxaB9cvNbNhjs0XNAv" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=debug msg="loading track (paused: true, position: 19298ms)" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=trace msg="emitting websocket event: will_play" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 310" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=warning msg="original track has no formats, alternatives have a total of 4" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=debug msg="selected format OGG_VORBIS_320 (c69e86f92f06fe26e3969f74cf49dca06b1a3640)" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:51 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:51+01:00" level=debug msg="requested aes key for file c69e86f92f06fe26e3969f74cf49dca06b1a3640, gid: 6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="fetched first chunk of 25, total size is 12857186 bytes" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="fetched chunk 1/24, size: 524288" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=trace msg="seek to 19298ms (diff: 164ms, samples: 851041, bytes: 735739)" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="created new output device" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=info msg="loaded track \"Not Everyone Is Lonely\" (paused: true, position: 19298ms, duration: 303400ms, prefetched: false)" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=trace msg="emitting websocket event: metadata" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=trace msg="emitting websocket event: active" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="sending successful reply for dealer request" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=trace msg="emitting websocket event: paused" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="fetched chunk 2/24, size: 524288" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="fetched chunk 3/24, size: 524288" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="fetched chunk 4/24, size: 524288" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:52 volumiopeter volumio[1167]: info: Initializing connection to go-librespot Websocket Mar 27 18:21:52 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:52+01:00" level=debug msg="new websocket client" Mar 27 18:21:52 volumiopeter volumio[1167]: info: Connection to go-librespot Websocket established Mar 27 18:21:54 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 18:21:54 volumiopeter volumio[1167]: info: Received Get System Info Mar 27 18:21:54 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 18:21:54 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 18:21:54 volumiopeter volumio[1167]: info: Discovery: Getting this device information Mar 27 18:21:54 volumiopeter volumio[1167]: info: CoreCommandRouter::volumioGetState Mar 27 18:21:54 volumiopeter volumio[1167]: info: CorePlayQueue::getTrack 0 Mar 27 18:21:54 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 18:21:54 volumiopeter volumio[1167]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 27 18:21:54 volumiopeter volumio[1167]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=debug msg="handling resume player command from b25140ebdecffdfe1d75871383b3c91a74676b2b" Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=trace msg="seek to 19298ms (diff: 164ms, samples: 851041, bytes: 735739)" uri="spotify:track:6BrhjcJIks6QnXmMKwqv87" Mar 27 18:21:55 volumiopeter volumio[1167]: info: FusionDsp - ---- read samplerate, raw: Mar 27 18:21:55 volumiopeter volumio[1167]: error: FusionDsp - invalid sample rate Mar 27 18:21:55 volumiopeter volumio[1167]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Mar 27 18:21:55 volumiopeter volumio[1167]: info: FusionDsp - ---- read samplerate from file: 44100 Mar 27 18:21:55 volumiopeter volumio[1167]: info: camilladsp stopping service pid 1934... Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=debug msg="resume track at 19134ms" Mar 27 18:21:55 volumiopeter volumio[1167]: info: camilladsp service terminated, instance 1 Mar 27 18:21:55 volumiopeter volumio[1167]: info: FusionDsp - File size found in array! Mar 27 18:21:55 volumiopeter volumio[1167]: info: FusionDsp - Nulleq applied Mar 27 18:21:55 volumiopeter volumio[1167]: info: camilladsp service started and running in background, instance 1 Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=trace msg="scheduling prefetch in 254s" Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=debug msg="sending successful reply for dealer request" Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 18:21:55 volumiopeter go-librespot[1825]: time="2026-03-27T18:21:55+01:00" level=trace msg="emitting websocket event: playing" Mar 27 18:21:55 volumiopeter volumio[1167]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:album:0KFEFxaB9cvNbNhjs0XNAv","uri":"spotify:track:6BrhjcJIks6QnXmMKwqv87","resume":true,"play_origin":"album"}} Mar 27 18:21:55 volumiopeter volumio[1167]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 18:21:55 volumiopeter volumio[1167]: TypeError: Cannot read property 'service' of undefined Mar 27 18:21:55 volumiopeter volumio[1167]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Mar 27 18:21:55 volumiopeter volumio[1167]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Mar 27 18:21:55 volumiopeter volumio[1167]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Mar 27 18:21:55 volumiopeter volumio[1167]: at WebSocket.emit (events.js:400:28) Mar 27 18:21:55 volumiopeter volumio[1167]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 27 18:21:55 volumiopeter volumio[1167]: at Receiver.emit (events.js:400:28) Mar 27 18:21:55 volumiopeter volumio[1167]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 27 18:21:55 volumiopeter volumio[1167]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 27 18:21:55 volumiopeter volumio[1167]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 27 18:21:55 volumiopeter volumio[1167]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 27 18:21:55 volumiopeter volumio[1167]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 18:21:55 volumiopeter sudo[2023]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-03-27 18:20 Mar 27 18:21:55 volumiopeter sudo[2023]: pam_unix(sudo:session): session opened for user root by (uid=0) 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="3dada8b1e619a5feb94867e0865ace17474d7bce" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="30045b259d1a704a832ca7c1460c1fdfa4b723f9" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 05 Mar 2026 12:25:22 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="tinkerboard" VOLUMIO_DEVICENAME="Asus Tinkerboard" VOLUMIO_HASH="cf5455596c5328b0cbc691c04ff0184a"