Apr 14 22:00:36 volumio ntpd[1126]: CLOCK: time stepped by 181181.468625 Apr 14 22:00:36 volumio ntpd[1126]: CLOCK: time changed from 2026-04-12 to 2026-04-14 Apr 14 22:00:36 volumio ntpd[1126]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02: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]" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02: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]" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02: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]" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=info msg="zeroconf server listening on port 39837" Apr 14 22:00:36 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Apr 14 22:00:36 volumio systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 14 22:00:36 volumio volumio[1229]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Apr 14 22:00:36 volumio systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Apr 14 22:00:36 volumio volumio[1229]: info: touch_display: systemctl daemon-reload succeeded. Apr 14 22:00:36 volumio volumio[1229]: info: MPD running with PID1449 Apr 14 22:00:36 volumio volumio[1229]: ,establishing connection Apr 14 22:00:36 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Apr 14 22:00:36 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="obtained new client token: AACb0ESDtqLYbGPCxKQ2m55AMoivM7Ohk/uJQxtG5c/ycD7U74IrlwSEZ68R3XM+vPhwLL7kA14Oe2C1rMJ9i6bhqsa3Mg12r3uLZhZ4m/LGUeqEJXS00pPyEXlTVkjZn+hZ59dWl99ZW1Lr1214ZOVNF+6hYJ07L8LWTe8Z9RWXE8z4cy93RymnHYG/7Kc0DHrZvZw/fI+iy2IFtt4Khd6AZgk7TceQXw1IMtGoGRdV6EVImab1bA==" Apr 14 22:00:36 volumio sudo[1673]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Apr 14 22:00:36 volumio sudo[1673]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Apr 14 22:00:36 volumio volumio[1229]: info: Discovery: this is already registered, a27cfcb4-8b81-484d-8059-e1bd2f0a13cd Apr 14 22:00:36 volumio volumio[1229]: info: Discovery: Found device Volumio Apr 14 22:00:36 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Apr 14 22:00:36 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:36 volumio systemd[1]: Started volumio-kiosk.service - Volumio Kiosk. Apr 14 22:00:36 volumio sudo[1673]: pam_unix(sudo:session): session closed for user root Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="completed keyexchange" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="completed challenge" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=info msg="authenticated AP" username="ma******ka" Apr 14 22:00:36 volumio startx[1700]: X.Org X Server 1.21.1.7 Apr 14 22:00:36 volumio startx[1700]: X Protocol Version 11, Revision 0 Apr 14 22:00:36 volumio startx[1700]: Current Operating System: Linux volumio 6.12.74-v7l+ #1948 SMP Mon Mar 2 11:27:49 GMT 2026 armv7l Apr 14 22:00:36 volumio startx[1700]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory numa_policy=interleave nvme.max_host_mem_size_mb=0 snd_bcm2835.enable_hdmi=0 video=HDMI-A-1:640x480M@60D numa=fake=2 system_heap.max_order=0 iommu_dma_numa_policy=interleave smsc95xx.macaddr=D8:3A:DD:34:E7:3A vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=9caf6474-168f-4972-add4-ace36a467bc2 imgfile=/volumio_current.sqsh bootpart=UUID=807D-2966 datapart=UUID=18edcea5-254e-4ab4-bc51-04b78bf2fc27 uuidconfig=cmdline.txt rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Apr 14 22:00:36 volumio startx[1700]: xorg-server 2:21.1.7-3+rpt3+deb12u11 (https://www.debian.org/support) Apr 14 22:00:36 volumio startx[1700]: Current version of pixman: 0.44.0 Apr 14 22:00:36 volumio startx[1700]: Before reporting problems, check http://wiki.x.org Apr 14 22:00:36 volumio startx[1700]: to make sure that you have the latest version. Apr 14 22:00:36 volumio startx[1700]: Markers: (--) probed, (**) from config file, (==) default setting, Apr 14 22:00:36 volumio startx[1700]: (++) from command line, (!!) notice, (II) informational, Apr 14 22:00:36 volumio startx[1700]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Apr 14 22:00:36 volumio startx[1700]: (==) Log file: "/var/log/Xorg.0.log", Time: Tue Apr 14 22:00:36 2026 Apr 14 22:00:36 volumio startx[1700]: (==) Using config directory: "/etc/X11/xorg.conf.d" Apr 14 22:00:36 volumio startx[1700]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=info msg="authenticated Login5" username="ma******ka" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="initializing zeroconf session" username="ma******ka" Apr 14 22:00:36 volumio volumio[1229]: error: [now-playing] Error fetching https://api.openweathermap.org/data/3.0/onecall?appid=1b73624457bda0fe861732554c535249&lat=50.091896&lon=20.015155&units=metric: Error: Response error: 401 - Unauthorized Apr 14 22:00:36 volumio volumio[1229]: at fetchPage (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:30:15) Apr 14 22:00:36 volumio volumio[1229]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Apr 14 22:00:36 volumio volumio[1229]: at async Promise.all (index 0) Apr 14 22:00:36 volumio volumio[1229]: at async fetchData (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:91:24) Apr 14 22:00:36 volumio volumio[1229]: at async OpenWeatherMapAPI.getWeather (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:104:45) Apr 14 22:00:36 volumio volumio[1229]: at async /data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:301:25 Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="dealer connection opened" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=trace msg="starting accesspoint recv loop" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=trace msg="starting dealer recv loop" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=trace msg="received accesspoint ping" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="received connection id: NzI4NGFhZmUtNTlh...NEMyMTNENkI1Nw==" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=trace msg="received accesspoint pong ack" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 14 22:00:36 volumio go-librespot[1645]: time="2026-04-14T22:00:36+02:00" level=debug msg="update volume requested to 65535/65535" Apr 14 22:00:37 volumio go-librespot[1645]: time="2026-04-14T22:00:37+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 14 22:00:37 volumio go-librespot[1645]: time="2026-04-14T22:00:37+02:00" level=trace msg="emitting websocket event: volume" Apr 14 22:00:37 volumio volumio[1229]: error: updateQueue error: null Apr 14 22:00:37 volumio volumio-remote-updater[812]: [2026-04-14 22:00:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1776015652 101 Apr 14 22:00:37 volumio volumio[1229]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 4 Apr 14 22:00:37 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Apr 14 22:00:37 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Apr 14 22:00:37 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Apr 14 22:00:37 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Apr 14 22:00:37 volumio upmpdcli[1701]: Could not open config: /tmp/upmpdcli.conf Apr 14 22:00:37 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Apr 14 22:00:37 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Apr 14 22:00:37 volumio volumio[1229]: info: touch_display: Raspberry Pi Foundation touch screen detected. Apr 14 22:00:37 volumio sudo[1706]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/10-0045/brightness Apr 14 22:00:37 volumio sudo[1706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 14 22:00:37 volumio sudo[1706]: pam_unix(sudo:session): session closed for user root Apr 14 22:00:37 volumio sudo[1713]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Apr 14 22:00:37 volumio sudo[1713]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 14 22:00:37 volumio sudo[1717]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Apr 14 22:00:37 volumio sudo[1717]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 14 22:00:37 volumio sudo[1713]: pam_unix(sudo:session): session closed for user root Apr 14 22:00:37 volumio volumio[1229]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Apr 14 22:00:37 volumio volumio[1229]: info: touch_display: Volumio Kiosk started. Apr 14 22:00:38 volumio sudo[1717]: pam_unix(sudo:session): session closed for user root Apr 14 22:00:38 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Apr 14 22:00:38 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:38 volumio volumio[1229]: info: Completed starting Core Plugins Apr 14 22:00:38 volumio volumio[1229]: info: ------------------------------------------- Apr 14 22:00:38 volumio volumio[1229]: info: ----- MyVolumio plugins startup ---- Apr 14 22:00:38 volumio volumio[1229]: info: ------------------------------------------- Apr 14 22:00:38 volumio volumio[1229]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 14 22:00:38 volumio kernel: ------------[ cut here ]------------ Apr 14 22:00:38 volumio kernel: WARNING: CPU: 2 PID: 1700 at drivers/gpu/drm/vc4/vc4_hvs.c:1064 __vc4_hvs_stop_channel+0x168/0x1dc [vc4] Apr 14 22:00:38 volumio kernel: Modules linked in: cmac algif_hash aes_arm_bs crypto_simd cryptd aes_arm aes_generic algif_skcipher af_alg bnep nft_chain_nat xt_REDIRECT nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xt_tcpudp nft_compat joydev nf_tables nfnetlink brcmfmac_wcc 8021q garp stp llc brcmfmac binfmt_misc snd_soc_pcm512x_i2c hci_uart btbcm brcmutil bluetooth cfg80211 snd_soc_allo_boss_dac bcm2835_isp(C) bcm2835_v4l2(C) bcm2835_codec(C) raspberrypi_hwmon snd_soc_pcm512x rpi_hevc_dec ecdh_generic ecc edt_ft5x06 bcm2835_mmal_vchiq(C) libaes v4l2_mem2mem rfkill videobuf2_dma_contig vc_sm_cma(C) videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videodev raspberrypi_gpiomem videobuf2_common mc nvmem_rmem uio_pdrv_genirq uio i2c_dev dm_mod ip_tables x_tables ipv6 ads7846 fb_hx8357d(C) fb_st7789v(C) fb_st7735r(C) fb_ili9341(C) fb_ili9340(C) fbtft(C) panel_waveshare_dsi_v2 panel_waveshare_dsi panel_ilitek_ili9881c panel_raspberrypi_touchscreen pwm_bcm2835 spi_bcm2835 squashfs overlay nls_iso8859_1 fuse rpi_panel_attiny_regulator Apr 14 22:00:38 volumio kernel: tc358762 regmap_i2c vc4 snd_soc_hdmi_codec drm_display_helper cec drm_dma_helper snd_soc_bcm2835_i2s v3d gpu_sched drm_shmem_helper snd_soc_core drm_kms_helper i2c_mux_pinctrl snd_compress i2c_mux snd_bcm2835(C) snd_pcm_dmaengine i2c_brcmstb snd_pcm i2c_bcm2835 snd_timer snd panel_simple drm drm_panel_orientation_quirks clk_hifiberry_dacpro backlight Apr 14 22:00:38 volumio kernel: CPU: 2 UID: 0 PID: 1700 Comm: Xorg Tainted: G C 6.12.74-v7l+ #1948 Apr 14 22:00:38 volumio kernel: Tainted: [C]=CRAP Apr 14 22:00:38 volumio kernel: Hardware name: BCM2711 Apr 14 22:00:38 volumio kernel: Call trace: Apr 14 22:00:38 volumio kernel: unwind_backtrace from show_stack+0x18/0x1c Apr 14 22:00:38 volumio kernel: show_stack from dump_stack_lvl+0x5c/0x80 Apr 14 22:00:38 volumio kernel: dump_stack_lvl from __warn+0x88/0x124 Apr 14 22:00:38 volumio kernel: __warn from warn_slowpath_fmt+0x184/0x190 Apr 14 22:00:38 volumio kernel: warn_slowpath_fmt from __vc4_hvs_stop_channel+0x168/0x1dc [vc4] Apr 14 22:00:38 volumio kernel: __vc4_hvs_stop_channel [vc4] from vc4_crtc_disable+0x138/0x1dc [vc4] Apr 14 22:00:38 volumio kernel: vc4_crtc_disable [vc4] from vc4_crtc_atomic_disable+0x9c/0xc0 [vc4] Apr 14 22:00:38 volumio kernel: vc4_crtc_atomic_disable [vc4] from disable_outputs+0x268/0x3a0 [drm_kms_helper] Apr 14 22:00:38 volumio kernel: disable_outputs [drm_kms_helper] from drm_atomic_helper_commit_modeset_disables+0x18/0x3c [drm_kms_helper] Apr 14 22:00:38 volumio kernel: drm_atomic_helper_commit_modeset_disables [drm_kms_helper] from vc4_atomic_commit_tail+0x194/0x998 [vc4] Apr 14 22:00:38 volumio kernel: vc4_atomic_commit_tail [vc4] from commit_tail+0xa4/0x18c [drm_kms_helper] Apr 14 22:00:38 volumio kernel: commit_tail [drm_kms_helper] from drm_atomic_helper_commit+0x140/0x164 [drm_kms_helper] Apr 14 22:00:38 volumio kernel: drm_atomic_helper_commit [drm_kms_helper] from drm_atomic_commit+0xc8/0x100 [drm] Apr 14 22:00:38 volumio kernel: drm_atomic_commit [drm] from drm_atomic_helper_set_config+0x90/0xc8 [drm_kms_helper] Apr 14 22:00:38 volumio kernel: drm_atomic_helper_set_config [drm_kms_helper] from drm_mode_setcrtc+0x200/0x814 [drm] Apr 14 22:00:38 volumio kernel: drm_mode_setcrtc [drm] from drm_ioctl+0x2b4/0x4d0 [drm] Apr 14 22:00:38 volumio kernel: drm_ioctl [drm] from sys_ioctl+0x130/0xbcc Apr 14 22:00:38 volumio kernel: sys_ioctl from ret_fast_syscall+0x0/0x5c Apr 14 22:00:38 volumio kernel: Exception stack(0xf0f7dfa8 to 0xf0f7dff0) Apr 14 22:00:38 volumio kernel: dfa0: 0000000c bedc19d0 0000000c c06864a2 bedc19d0 bedc19b0 Apr 14 22:00:38 volumio kernel: dfc0: 0000000c bedc19d0 c06864a2 00000036 bedc1a88 01f00130 015126b8 00000000 Apr 14 22:00:38 volumio kernel: dfe0: 00000000 bedc1998 b6a15000 b69981e4 Apr 14 22:00:38 volumio kernel: ---[ end trace 0000000000000000 ]--- Apr 14 22:00:38 volumio volumio[1229]: error: updateQueue error: null Apr 14 22:00:38 volumio volumio[1229]: info: Volumio Network Manager: Network status updated: 1 Apr 14 22:00:38 volumio volumio[1229]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Apr 14 22:00:38 volumio volumio[1229]: info: touch_display: X display number found: 0 Apr 14 22:00:38 volumio volumio[1229]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Apr 14 22:00:38 volumio volumio[1229]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Apr 14 22:00:38 volumio volumio[1229]: info: touch_display: File permissions for backlight brightness control set. Apr 14 22:00:38 volumio volumio[1229]: info: New Spotify access tokenBQDalrjmFn... Apr 14 22:00:38 volumio volumio[1229]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 14 22:00:38 volumio volumio[1229]: error: [now-playing] Error fetching https://api.openweathermap.org/data/3.0/onecall?appid=1b73624457bda0fe861732554c535249&lat=50.091896&lon=20.015155&units=metric: Error: Response error: 401 - Unauthorized Apr 14 22:00:38 volumio volumio[1229]: at fetchPage (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:30:15) Apr 14 22:00:38 volumio volumio[1229]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Apr 14 22:00:38 volumio volumio[1229]: at async Promise.all (index 0) Apr 14 22:00:38 volumio volumio[1229]: at async fetchData (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:91:24) Apr 14 22:00:38 volumio volumio[1229]: at async OpenWeatherMapAPI.getWeather (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:104:45) Apr 14 22:00:38 volumio volumio[1229]: at async /data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:301:25 Apr 14 22:00:38 volumio volumio[1229]: error: [now-playing] Caught error in callback of WeatherAPI.#getFetchPromise(): Response error: 401 - Unauthorized Apr 14 22:00:39 volumio volumio[1229]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 14 22:00:39 volumio volumio[1229]: info: touch_display: X display number found: 0 Apr 14 22:00:39 volumio volumio[1229]: info: go-librespot daemon successfully initialized Apr 14 22:00:39 volumio volumio[1229]: info: Discovery: A device disappeared from network Apr 14 22:00:39 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Apr 14 22:00:39 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:39 volumio volumio[1229]: info: Discovery: A device disappeared from network Apr 14 22:00:40 volumio volumio[1229]: info: touch_display: Setting screensaver timeout to 300 seconds. Apr 14 22:00:40 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Apr 14 22:00:40 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:40 volumio volumio[1229]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Apr 14 22:00:40 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Apr 14 22:00:40 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:40 volumio go-librespot[1645]: time="2026-04-14T22:00:40+02:00" level=debug msg="handling transfer player command from 2e4c478d79ecc7ee757ab297f67afe310281188e" Apr 14 22:00:40 volumio go-librespot[1645]: time="2026-04-14T22:00:40+02:00" level=debug msg="resolved context of track" uri="spotify:artist:5icKdCmMhNMYoAzVBAWt39" Apr 14 22:00:40 volumio go-librespot[1645]: time="2026-04-14T22:00:40+02:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:5icKdCmMhNMYoAzVBAWt39" Apr 14 22:00:40 volumio go-librespot[1645]: time="2026-04-14T22:00:40+02:00" level=trace msg="fetched new page 1 with 41 items (list: 51)" uri="spotify:artist:5icKdCmMhNMYoAzVBAWt39" Apr 14 22:00:40 volumio go-librespot[1645]: time="2026-04-14T22:00:40+02:00" level=debug msg="loading track (paused: true, position: 27351ms)" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:40 volumio volumio[1229]: info: Discovery: adding a27cfcb4-8b81-484d-8059-e1bd2f0a13cd Apr 14 22:00:40 volumio volumio[1229]: info: Discovery: Found device Volumio Apr 14 22:00:40 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Apr 14 22:00:40 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:40 volumio go-librespot[1645]: time="2026-04-14T22:00:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 14 22:00:40 volumio go-librespot[1645]: time="2026-04-14T22:00:40+02:00" level=trace msg="emitting websocket event: will_play" Apr 14 22:00:40 volumio go-librespot[1645]: time="2026-04-14T22:00:40+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Apr 14 22:00:41 volumio volumio[1229]: info: Discovery: this is already registered, a27cfcb4-8b81-484d-8059-e1bd2f0a13cd Apr 14 22:00:41 volumio volumio[1229]: info: Discovery: Found device Volumio Apr 14 22:00:41 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Apr 14 22:00:41 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1686" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="selected format OGG_VORBIS_320 (2c5c308d8bffbaba0519b07048447ca27fd19868)" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="requested aes key for file 2c5c308d8bffbaba0519b07048447ca27fd19868, gid: 6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio volumio[1229]: SPOTIFY: User informations: {"country":"PL","display_name":"marek.mika","email":"marek.mika@o2.pl","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/marek.mika"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/marek.mika","id":"marek.mika","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85b9cc7842a8bd6728c4907d1b","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82b9cc7842a8bd6728c4907d1b","width":64}],"product":"premium","type":"user","uri":"spotify:user:marek.mika"} Apr 14 22:00:41 volumio volumio[1229]: info: Spotify Successfully logged in Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1296" Apr 14 22:00:41 volumio volumio[1229]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 22:00:41 volumio volumio[1229]: info: [1776196841444] CoreMusicLibrary::Adding element Spotify Apr 14 22:00:41 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 22:00:41 volumio volumio[1229]: Cannot find translation for source Spotify Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="fetched first chunk of 20, total size is 10292579 bytes" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=trace msg="seek to 27351ms (diff: 91ms, samples: 1206179, bytes: 1183275)" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="created new output device" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=info msg="loaded track \"God, Can You Hear Me?\" (paused: true, position: 27351ms, duration: 253658ms, prefetched: false)" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=trace msg="emitting websocket event: metadata" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=trace msg="emitting websocket event: active" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="sending successful reply for dealer request" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="fetched chunk 5/19, size: 524288" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=trace msg="emitting websocket event: paused" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:41 volumio go-librespot[1645]: time="2026-04-14T22:00:41+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:42 volumio volumio[1229]: info: New access token = BQBWcYqTJPLdaqElGnzow8E3Wy2rPwBHtR8V3pW2eenAzXTzyj_ZA100M_Xppgy9xB4auLJSAFYWzZbVKmvO-0Ch5MJnnYIEEWdjFDqdkWFRZkY9qeb7qB4ffI9xIWpEelLA3NsvtmmhiH6qNE-B21320I1YdZ8PhnPuP2zKaSR_NQpe2kn0DT8mZ6uMrOI3H8FCVpsPwx_ZTnE-ZHUG2oG8_ORpVmxbCTZrLVdLkj3aAG_ucXq3MgkQUUZ70nfqnufchbi87U5_ICr1h8i_FTtlqnkcdejWO3sJkA Apr 14 22:00:42 volumio volumio[1229]: info: Initializing connection to go-librespot Websocket Apr 14 22:00:42 volumio go-librespot[1645]: time="2026-04-14T22:00:42+02:00" level=debug msg="new websocket client" Apr 14 22:00:42 volumio volumio[1229]: info: Connection to go-librespot Websocket established Apr 14 22:00:42 volumio volumio[1229]: info: New access token = BQDR7453VoG62HfqeWDUjEHJNbJ4nZv-bgilNzrvOFY-gkesL-G9SvKhZBMuiX2k7uCC0tnd93dd4V8Crunbvbpt0608RGo0afmdpW52m-Bx3imd8hF4iUKD0j6XXYCs30CnjeTFUiqBcuON_WL1S-on01qv3GePB3HgM5oLZsT6JPK7wCn0ZptN4h1WgL70jxT3ASxk3DgJKsKsG1AByNuLFcy2VqEqQcIiEdBPZU4QmxjmhnJ-izFMGKpCK6Pk8_LygbwjA2kdBa15tgAVvo9Dg99hEZDzxF1Iew Apr 14 22:00:43 volumio volumio[1229]: info: New access token = BQCqUoF2NXeTECwazLYYTrUzGisXn_7OIPJoAL6Zv1g82A0EVZJNajAo4TbD7Z6TqBegx0nBoWBiOmMT4ud3787GoxhBKbRL7ROUHT14LQ8DlRIXh8dSXfFL-aqYCi7DtCZEThbsmg38A2Y5Lcoi2gLKmIMVkogO9-HUpADsZa5uHJxe_UxUsV5TzVfuaWJM7e1ioVGb3n8k2vzF7bt0B18EnSMRviJa3BA3H4t5WDAUcK0LEdBFC7iUsoVd8JT29kt-AUkcKJ__gp9YedTD4IfK1RpMmqWXaQX00w Apr 14 22:00:44 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Apr 14 22:00:45 volumio go-librespot[1645]: time="2026-04-14T22:00:45+02:00" level=debug msg="handling seek_to player command from 2e4c478d79ecc7ee757ab297f67afe310281188e" Apr 14 22:00:45 volumio go-librespot[1645]: time="2026-04-14T22:00:45+02:00" level=debug msg="seek track to 452ms" Apr 14 22:00:45 volumio go-librespot[1645]: time="2026-04-14T22:00:45+02:00" level=trace msg="seek to 452ms (diff: -98ms, samples: 19933, bytes: 18459)" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:45 volumio go-librespot[1645]: time="2026-04-14T22:00:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 14 22:00:45 volumio go-librespot[1645]: time="2026-04-14T22:00:45+02:00" level=trace msg="emitting websocket event: seek" Apr 14 22:00:45 volumio go-librespot[1645]: time="2026-04-14T22:00:45+02:00" level=debug msg="sending successful reply for dealer request" Apr 14 22:00:45 volumio volumio[1229]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:artist:5icKdCmMhNMYoAzVBAWt39","uri":"spotify:track:6kRIm62wf9TyvqjSnmpMrK","position":452,"duration":253658,"play_origin":"free-tier-artist"}} Apr 14 22:00:45 volumio volumio[1229]: SPOTIFY: PUSH STATE SPOTIFY Apr 14 22:00:45 volumio volumio[1229]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":452,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 14 22:00:45 volumio volumio[1229]: info: CoreCommandRouter::servicePushState Apr 14 22:00:45 volumio volumio[1229]: info: CoreStateMachine::pushState Apr 14 22:00:45 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:45 volumio volumio[1229]: info: CoreCommandRouter::volumioPushState Apr 14 22:00:45 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Apr 14 22:00:45 volumio volumio[1229]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received spop Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=debug msg="handling resume player command from 2e4c478d79ecc7ee757ab297f67afe310281188e" Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=trace msg="seek to 452ms (diff: -98ms, samples: 19933, bytes: 18459)" uri="spotify:track:6kRIm62wf9TyvqjSnmpMrK" Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=debug msg="resume track at 550ms" Apr 14 22:00:46 volumio volumio[1229]: info: Getting Spotify volume Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=trace msg="scheduling prefetch in 223s" Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=debug msg="sending successful reply for dealer request" Apr 14 22:00:46 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Apr 14 22:00:46 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 14 22:00:46 volumio go-librespot[1645]: time="2026-04-14T22:00:46+02:00" level=trace msg="emitting websocket event: playing" Apr 14 22:00:46 volumio volumio[1229]: info: Spotify volume: 100 Apr 14 22:00:46 volumio volumio[1229]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:artist:5icKdCmMhNMYoAzVBAWt39","uri":"spotify:track:6kRIm62wf9TyvqjSnmpMrK","resume":true,"play_origin":"free-tier-artist"}} Apr 14 22:00:46 volumio volumio[1229]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 22:00:46 volumio volumio[1229]: TypeError: Cannot read properties of undefined (reading 'service') Apr 14 22:00:46 volumio volumio[1229]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Apr 14 22:00:46 volumio volumio[1229]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Apr 14 22:00:46 volumio volumio[1229]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Apr 14 22:00:46 volumio volumio[1229]: at WebSocket.emit (node:events:514:28) Apr 14 22:00:46 volumio volumio[1229]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Apr 14 22:00:46 volumio volumio[1229]: at Receiver.emit (node:events:514:28) Apr 14 22:00:46 volumio volumio[1229]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Apr 14 22:00:46 volumio volumio[1229]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Apr 14 22:00:46 volumio volumio[1229]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Apr 14 22:00:46 volumio volumio[1229]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Apr 14 22:00:46 volumio volumio[1229]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 22:00:49 volumio sudo[2101]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-14 21:59' Apr 14 22:00:49 volumio sudo[2101]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"