Dec 25 23:38:05 volumio-mf kernel: node invoked oom-killer: gfp_mask=0x140cca(GFP_HIGHUSER_MOVABLE|__GFP_COMP), order=0, oom_score_adj=0 Dec 25 23:38:05 volumio-mf kernel: CPU: 0 UID: 1000 PID: 1309 Comm: node Tainted: G C 6.12.47-v8+ #1904 Dec 25 23:38:05 volumio-mf kernel: Tainted: [C]=CRAP Dec 25 23:38:05 volumio-mf kernel: Hardware name: Raspberry Pi 5 Model B Rev 1.1 (DT) Dec 25 23:38:05 volumio-mf kernel: Call trace: Dec 25 23:38:05 volumio-mf kernel: dump_backtrace+0x9c/0x100 Dec 25 23:38:05 volumio-mf kernel: show_stack+0x20/0x38 Dec 25 23:38:05 volumio-mf kernel: dump_stack_lvl+0x78/0x90 Dec 25 23:38:05 volumio-mf kernel: dump_stack+0x18/0x28 Dec 25 23:38:05 volumio-mf kernel: dump_header+0x48/0x1b0 Dec 25 23:38:05 volumio-mf kernel: oom_kill_process+0x138/0x368 Dec 25 23:38:05 volumio-mf kernel: out_of_memory+0xe4/0x598 Dec 25 23:38:05 volumio-mf kernel: __alloc_pages_noprof+0xad8/0xdf0 Dec 25 23:38:05 volumio-mf kernel: alloc_pages_mpol_noprof+0x5c/0x158 Dec 25 23:38:05 volumio-mf kernel: alloc_pages_noprof+0x58/0x98 Dec 25 23:38:05 volumio-mf kernel: folio_alloc_noprof+0x1c/0x38 Dec 25 23:38:05 volumio-mf kernel: filemap_alloc_folio_noprof+0x144/0x160 Dec 25 23:38:05 volumio-mf kernel: __filemap_get_folio+0x140/0x310 Dec 25 23:38:05 volumio-mf kernel: filemap_fault+0x58c/0x950 Dec 25 23:38:05 volumio-mf kernel: __do_fault+0x44/0x148 Dec 25 23:38:05 volumio-mf kernel: __handle_mm_fault+0x4e0/0xcb8 Dec 25 23:38:05 volumio-mf kernel: handle_mm_fault+0xe0/0x2c8 Dec 25 23:38:05 volumio-mf kernel: do_page_fault+0x108/0x578 Dec 25 23:38:05 volumio-mf kernel: do_translation_fault+0xb4/0xd8 Dec 25 23:38:05 volumio-mf kernel: do_mem_abort+0x4c/0xa8 Dec 25 23:38:05 volumio-mf kernel: el0_da+0x2c/0xa0 Dec 25 23:38:05 volumio-mf kernel: el0t_32_sync_handler+0x11c/0x148 Dec 25 23:38:05 volumio-mf kernel: el0t_32_sync+0x194/0x198 Dec 25 23:38:05 volumio-mf kernel: Mem-Info: Dec 25 23:38:05 volumio-mf kernel: active_anon:30338 inactive_anon:37301 isolated_anon:0 active_file:55734 inactive_file:56056 isolated_file:0 unevictable:4097 dirty:38085 writeback:0 slab_reclaimable:11741 slab_unreclaimable:8960 mapped:16161 shmem:1991 pagetables:1721 sec_pagetables:0 bounce:0 kernel_misc_reclaimable:0 free:287344 free_pcp:196 free_cma:12004 Dec 25 23:38:05 volumio-mf kernel: Node 0 active_anon:107668kB inactive_anon:149204kB active_file:153432kB inactive_file:24kB unevictable:10436kB isolated(anon):0kB isolated(file):0kB mapped:4816kB dirty:152332kB writeback:0kB shmem:5728kB writeback_tmp:0kB kernel_stack:3544kB pagetables:5772kB sec_pagetables:0kB all_unreclaimable? yes Dec 25 23:38:05 volumio-mf kernel: Node 0 DMA free:3636kB boost:0kB min:3980kB low:4972kB high:5964kB reserved_highatomic:0KB active_anon:107668kB inactive_anon:149204kB active_file:153300kB inactive_file:156kB unevictable:10436kB writepending:152332kB present:524288kB managed:492956kB mlocked:10436kB bounce:0kB free_pcp:784kB local_pcp:376kB free_cma:0kB Dec 25 23:38:05 volumio-mf kernel: lowmem_reserve[]: 0 0 0 0 Dec 25 23:38:05 volumio-mf kernel: Node 0 DMA: 1*4kB (U) 17*8kB (UME) 46*16kB (UME) 22*32kB (UME) 16*64kB (ME) 3*128kB (ME) 2*256kB (E) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3500kB Dec 25 23:38:05 volumio-mf kernel: 115378 total pagecache pages Dec 25 23:38:05 volumio-mf kernel: 0 pages in swap cache Dec 25 23:38:05 volumio-mf kernel: Free swap = 0kB Dec 25 23:38:05 volumio-mf kernel: Total swap = 0kB Dec 25 23:38:05 volumio-mf kernel: 522240 pages RAM Dec 25 23:38:05 volumio-mf kernel: 0 pages HighMem/MovableOnly Dec 25 23:38:05 volumio-mf kernel: 15133 pages reserved Dec 25 23:38:05 volumio-mf kernel: 16384 pages cma reserved Dec 25 23:38:05 volumio-mf kernel: Tasks state (memory values in pages): Dec 25 23:38:05 volumio-mf kernel: [ pid ] uid tgid total_vm rss rss_anon rss_file rss_shmem pgtables_bytes swapents oom_score_adj name Dec 25 23:38:05 volumio-mf kernel: [ 503] 0 503 7673 2141 192 1309 640 73728 0 -250 systemd-journal Dec 25 23:38:05 volumio-mf kernel: [ 530] 0 530 6021 1145 256 889 0 57344 0 -1000 systemd-udevd Dec 25 23:38:05 volumio-mf kernel: [ 889] 0 889 1995 1167 770 397 0 45056 0 0 haveged Dec 25 23:38:05 volumio-mf kernel: [ 892] 100 892 602 512 32 480 0 32768 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 893] 0 893 564 429 32 397 0 32768 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 894] 100 894 559 276 32 244 0 32768 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 895] 100 895 559 244 32 212 0 32768 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 898] 108 898 1730 780 64 716 0 40960 0 0 rpcbind Dec 25 23:38:05 volumio-mf kernel: [ 974] 103 974 1588 764 64 700 0 45056 0 0 avahi-daemon Dec 25 23:38:05 volumio-mf kernel: [ 975] 0 975 2807 1182 64 1118 0 49152 0 0 bluetoothd Dec 25 23:38:05 volumio-mf kernel: [ 976] 101 976 1857 853 96 757 0 49152 0 -900 dbus-daemon Dec 25 23:38:05 volumio-mf kernel: [ 981] 0 981 7663 1351 128 1223 0 61440 0 0 systemd-logind Dec 25 23:38:05 volumio-mf kernel: [ 983] 65534 983 1249 528 32 496 0 36864 0 0 thd Dec 25 23:38:05 volumio-mf kernel: [ 986] 1000 986 11914 2278 224 2054 0 90112 0 0 volumio-remote- Dec 25 23:38:05 volumio-mf kernel: [ 989] 0 989 31861 7280 1288 5992 0 241664 0 0 node Dec 25 23:38:05 volumio-mf kernel: [ 1006] 103 1006 1544 369 32 337 0 40960 0 0 avahi-daemon Dec 25 23:38:05 volumio-mf kernel: [ 1017] 100 1017 602 437 32 405 0 28672 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 1018] 0 1018 642 460 32 428 0 28672 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 1019] 100 1019 559 280 32 248 0 28672 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 1021] 100 1021 559 280 32 248 0 28672 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 1084] 0 1084 3274 1208 96 1112 0 49152 0 0 wpa_supplicant Dec 25 23:38:05 volumio-mf kernel: [ 1085] 0 1085 11193 1571 128 1443 0 90112 0 0 bluealsa Dec 25 23:38:05 volumio-mf kernel: [ 1117] 0 1117 1406 665 32 633 0 40960 0 0 bash Dec 25 23:38:05 volumio-mf kernel: [ 1119] 0 1119 929 581 32 549 0 36864 0 0 ip Dec 25 23:38:05 volumio-mf kernel: [ 1120] 0 1120 1392 429 0 429 0 45056 0 0 sed Dec 25 23:38:05 volumio-mf kernel: [ 1121] 0 1121 1406 382 32 350 0 40960 0 0 bash Dec 25 23:38:05 volumio-mf kernel: [ 1130] 106 1130 4360 4004 2423 1581 0 61440 0 0 ntpd Dec 25 23:38:05 volumio-mf kernel: [ 1140] 0 1140 519 347 0 347 0 28672 0 0 ifplugd Dec 25 23:38:05 volumio-mf kernel: [ 1148] 0 1148 3390 1839 192 1647 0 53248 0 -1000 sshd Dec 25 23:38:05 volumio-mf kernel: [ 1192] 0 1192 16454 2511 416 2025 70 102400 0 0 nmbd Dec 25 23:38:05 volumio-mf kernel: [ 1203] 0 1203 16380 938 407 531 0 98304 0 0 nmbd Dec 25 23:38:05 volumio-mf kernel: [ 1244] 100 1244 564 308 33 275 0 32768 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 1267] 100 1267 642 341 66 275 0 28672 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 1309] 1000 1309 75725 31103 24186 6917 0 1200128 0 0 node Dec 25 23:38:05 volumio-mf kernel: [ 1330] 0 1330 1114 427 0 427 0 36864 0 0 agetty Dec 25 23:38:05 volumio-mf kernel: [ 1337] 0 1337 1125 470 0 470 0 36864 0 0 agetty Dec 25 23:38:05 volumio-mf kernel: [ 1392] 1000 1392 1397 641 32 609 0 40960 0 0 network_monitor Dec 25 23:38:05 volumio-mf kernel: [ 1456] 100 1456 564 341 33 308 0 32768 0 0 dhcpcd Dec 25 23:38:05 volumio-mf kernel: [ 1487] 0 1487 18060 2643 480 2091 72 114688 0 0 winbindd Dec 25 23:38:05 volumio-mf kernel: [ 1494] 0 1494 18120 2356 513 1805 38 114688 0 0 winbindd Dec 25 23:38:05 volumio-mf kernel: [ 1501] 0 1501 19289 2981 512 2275 194 118784 0 0 smbd Dec 25 23:38:05 volumio-mf kernel: [ 1512] 0 1512 18896 1938 504 1434 0 114688 0 0 smbd-notifyd Dec 25 23:38:05 volumio-mf kernel: [ 1513] 0 1513 18896 1106 504 602 0 114688 0 0 cleanupd Dec 25 23:38:05 volumio-mf kernel: [ 1517] 0 1517 18060 1886 484 1402 0 110592 0 0 winbindd Dec 25 23:38:05 volumio-mf kernel: [ 1521] 1000 1521 31610 6722 891 5831 0 217088 0 0 node Dec 25 23:38:05 volumio-mf kernel: [ 1531] 1000 1531 32737 8358 2275 6083 0 290816 0 0 node Dec 25 23:38:05 volumio-mf kernel: [ 1532] 1000 1532 32690 8297 2228 6069 0 286720 0 0 node Dec 25 23:38:05 volumio-mf kernel: [ 1533] 1000 1533 32599 8356 2238 6118 0 278528 0 0 node Dec 25 23:38:05 volumio-mf kernel: [ 1575] 0 1575 3359 662 195 467 0 57344 0 0 wpa_supplicant Dec 25 23:38:05 volumio-mf kernel: [ 1789] 1000 1789 514 290 0 290 0 32768 0 0 start-go-libres Dec 25 23:38:05 volumio-mf kernel: [ 1790] 1000 1790 154898 5662 5037 625 0 221184 0 0 go-librespot Dec 25 23:38:05 volumio-mf kernel: [ 1932] 1000 1932 36122 2788 416 2372 0 147456 0 0 upmpdcli Dec 25 23:38:05 volumio-mf kernel: [ 2170] 102 2170 133925 22331 18368 3963 0 778240 0 0 mpd Dec 25 23:38:05 volumio-mf kernel: [ 2204] 1000 2204 6908 2231 320 1911 0 81920 0 0 qobuz-connect-d Dec 25 23:38:05 volumio-mf kernel: [ 2222] 104 2222 37564 2635 441 2194 0 155648 0 0 shairport-sync Dec 25 23:38:05 volumio-mf kernel: [ 2272] 1000 2272 514 314 0 314 0 32768 0 0 sh Dec 25 23:38:05 volumio-mf kernel: [ 2273] 1000 2273 70111 4119 928 3191 0 294912 0 0 vtcs Dec 25 23:38:05 volumio-mf kernel: [ 2470] 1000 2470 514 308 0 308 0 28672 0 0 sshtunnel.sh Dec 25 23:38:05 volumio-mf kernel: [ 2471] 1000 2471 495 329 0 329 0 24576 0 0 autossh Dec 25 23:38:05 volumio-mf kernel: [ 2474] 1000 2474 2960 1480 224 1256 0 49152 0 0 ssh Dec 25 23:38:05 volumio-mf kernel: [ 15645] 1000 15645 514 311 0 311 0 32768 0 0 sh Dec 25 23:38:05 volumio-mf kernel: [ 15646] 1000 15646 2628 1415 192 1223 0 45056 0 0 rsync Dec 25 23:38:05 volumio-mf kernel: [ 15647] 1000 15647 2571 1199 101 1098 0 45056 0 0 rsync Dec 25 23:38:05 volumio-mf kernel: [ 15648] 1000 15648 2636 429 199 230 0 40960 0 0 rsync Dec 25 23:38:05 volumio-mf kernel: oom-kill:constraint=CONSTRAINT_CPUSET,nodemask=(null),cpuset=system,mems_allowed=0,global_oom,task_memcg=/,task=node,pid=1309,uid=1000 Dec 25 23:38:05 volumio-mf kernel: Out of memory: Killed process 1309 (node) total-vm:302900kB, anon-rss:96744kB, file-rss:27668kB, shmem-rss:0kB, UID:1000 pgtables:1172kB oom_score_adj:0 Dec 25 23:38:05 volumio-mf vtcs[2273]: [2025-12-25 23:38:05.124] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=trace msg="received accesspoint ping" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=trace msg="sent dealer ping" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=error msg="did not receive last pong ack from accesspoint, 133s passed" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=trace msg="received accesspoint pong ack" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.1.8:53908->104.199.65.9:4070: use of closed network connection" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=trace msg="received dealer pong" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="completed keyexchange" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="completed challenge" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=info msg="authenticated AP" username="dh***os" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=trace msg="received accesspoint ping" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="re-established accesspoint connection" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 25 23:38:05 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:05Z" level=trace msg="received accesspoint pong ack" Dec 25 23:38:05 volumio-mf qobuz-connect[2204]: 20251225 23:38:05.101 [2204.2204] INFO SampleApp: Socket closed Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:05 volumio-mf systemd[1]: volumio.service: Main process exited, code=killed, status=9/KILL Dec 25 23:38:05 volumio-mf systemd[1]: volumio.service: Failed with result 'signal'. Dec 25 23:38:05 volumio-mf systemd[1]: volumio.service: Consumed 1min 22.202s CPU time. Dec 25 23:38:05 volumio-mf systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 25 23:38:05 volumio-mf systemd[1]: dynamicswap.service: Deactivated successfully. Dec 25 23:38:06 volumio-mf systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Dec 25 23:38:06 volumio-mf systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 25 23:38:06 volumio-mf systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 25 23:38:06 volumio-mf systemd[1]: volumio.service: Consumed 1min 22.202s CPU time. Dec 25 23:38:06 volumio-mf systemd[1]: Started volumio.service - Volumio Backend Module. Dec 25 23:38:06 volumio-mf systemd[1]: dynamicswap.service: Deactivated successfully. Dec 25 23:38:06 volumio-mf volumio-remote-updater[986]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:06 volumio-mf volumio-remote-updater[986]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:06 volumio-mf volumio-remote-updater[986]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:06 volumio-mf volumio-remote-updater[986]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:07 volumio-mf volumio-remote-updater[986]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:07 volumio-mf volumio-remote-updater[986]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:07 volumio-mf volumio-remote-updater[986]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:07 volumio-mf volumio-remote-updater[986]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:08 volumio-mf volumio-remote-updater[986]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:08 volumio-mf volumio-remote-updater[986]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:08 volumio-mf volumio-remote-updater[986]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:08 volumio-mf volumio-remote-updater[986]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:09 volumio-mf volumio-remote-updater[986]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:09 volumio-mf volumio-remote-updater[986]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:09 volumio-mf volumio-remote-updater[986]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:09 volumio-mf volumio-remote-updater[986]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:10 volumio-mf volumio-remote-updater[986]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:10 volumio-mf volumio-remote-updater[986]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:10 volumio-mf volumio-remote-updater[986]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:10 volumio-mf volumio-remote-updater[986]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:11 volumio-mf volumio-remote-updater[986]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:11 volumio-mf volumio-remote-updater[986]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:11 volumio-mf volumio-remote-updater[986]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:11 volumio-mf volumio-remote-updater[986]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:12 volumio-mf volumio-remote-updater[986]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:12 volumio-mf volumio-remote-updater[986]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:12 volumio-mf volumio-remote-updater[986]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:12 volumio-mf volumio-remote-updater[986]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:13 volumio-mf volumio-remote-updater[986]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:13 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:13 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:13 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:14 volumio-mf volumio[15742]: info: ------------------------------------------- Dec 25 23:38:14 volumio-mf volumio[15742]: info: ----- Volumio3 ---- Dec 25 23:38:14 volumio-mf volumio[15742]: info: ------------------------------------------- Dec 25 23:38:14 volumio-mf volumio[15742]: info: ----- System startup ---- Dec 25 23:38:14 volumio-mf volumio[15742]: info: ------------------------------------------- Dec 25 23:38:15 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:15 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:15 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:15 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:16 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:16 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:16 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:16 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:16 volumio-mf volumio[15742]: info: MYVOLUMIO Environment detected Dec 25 23:38:17 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:17 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:17 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:17 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:19 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:19 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:19 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:19 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio[15742]: info: Plugin folders cleanup Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning into folder /volumio/app/plugins/ Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category audio_interface Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category miscellanea Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category music_service Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category plugins.json Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category system_controller Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category user_interface Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning into folder /data/plugins/ Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category music_service Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category system_controller Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category system_hardware Dec 25 23:38:20 volumio-mf volumio[15742]: info: Scanning category user_interface Dec 25 23:38:20 volumio-mf volumio[15742]: info: Plugin folders cleanup completed Dec 25 23:38:20 volumio-mf volumio[15742]: info: ------------------------------------------- Dec 25 23:38:20 volumio-mf volumio[15742]: info: ----- Core plugins startup ---- Dec 25 23:38:20 volumio-mf volumio[15742]: info: ------------------------------------------- Dec 25 23:38:20 volumio-mf volumio[15742]: info: Loading plugins from folder /volumio/app/plugins/ Dec 25 23:38:20 volumio-mf volumio[15742]: info: Adding plugin upnp to MyMusic Plugins Dec 25 23:38:20 volumio-mf volumio[15742]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 25 23:38:20 volumio-mf volumio[15742]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 25 23:38:20 volumio-mf volumio[15742]: info: Loading plugins from folder /data/plugins/ Dec 25 23:38:20 volumio-mf volumio[15742]: info: Loading plugin "system"... Dec 25 23:38:20 volumio-mf volumio[15742]: info: Loading plugin "appearance"... Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:20 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "network"... Dec 25 23:38:21 volumio-mf volumio[15742]: info: Refreshing Cached IP Addresses Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "services"... Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "alsa_controller"... Dec 25 23:38:21 volumio-mf sudo[15794]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 25 23:38:21 volumio-mf sudo[15783]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 25 23:38:21 volumio-mf sudo[15781]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 25 23:38:21 volumio-mf sudo[15783]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:21 volumio-mf sudo[15794]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:21 volumio-mf sudo[15781]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:21 volumio-mf sudo[15783]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:21 volumio-mf sudo[15781]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:21 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "wizard"... Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "networkfs"... Dec 25 23:38:21 volumio-mf volumio[15742]: info: Cannot mount NAS NAS_Music at system boot, trial number 1 ,retrying in 5 seconds Dec 25 23:38:21 volumio-mf volumio[15742]: info: Starting Udev Watcher for removable devices Dec 25 23:38:21 volumio-mf volumio[15742]: info: Ignoring mount for partition: boot Dec 25 23:38:21 volumio-mf volumio[15742]: info: Ignoring mount for partition: volumio Dec 25 23:38:21 volumio-mf volumio[15742]: info: Ignoring mount for partition: volumio_data Dec 25 23:38:21 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "volumio_command_line_client"... Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "upnp"... Dec 25 23:38:21 volumio-mf volumio[15742]: info: [1766705901704] Starting Upmpd Daemon Dec 25 23:38:21 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "my_music"... Dec 25 23:38:21 volumio-mf volumio[15742]: info: Loading plugin "mpd"... Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 29, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 29, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 29, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 29, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:21 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" Dec 25 23:38:22 volumio-mf volumio[15742]: info: Loading plugin "upnp_browser"... Dec 25 23:38:24 volumio-mf sudo[15794]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:24 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:25 volumio-mf volumio[15742]: info: Starting UPNP Browser Dec 25 23:38:25 volumio-mf volumio[15742]: info: Loading plugin "alarm-clock"... Dec 25 23:38:25 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:25 volumio-mf volumio[15742]: info: Loading plugin "airplay_emulation"... Dec 25 23:38:25 volumio-mf volumio[15742]: info: Starting Shairport Sync Dec 25 23:38:25 volumio-mf volumio[15742]: info: Loading plugin "last_100"... Dec 25 23:38:25 volumio-mf volumio[15742]: info: Loading plugin "webradio"... Dec 25 23:38:25 volumio-mf volumio[15742]: info: Loading plugin "i2s_dacs"... Dec 25 23:38:25 volumio-mf volumio[15742]: info: Loading plugin "volumiodiscovery"... Dec 25 23:38:25 volumio-mf volumio[15742]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 25 23:38:25 volumio-mf node[15742]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 25 23:38:25 volumio-mf volumio[15742]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 25 23:38:25 volumio-mf node[15742]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 25 23:38:25 volumio-mf volumio[15742]: *** WARNING *** For more information see Dec 25 23:38:25 volumio-mf node[15742]: *** WARNING *** For more information see Dec 25 23:38:25 volumio-mf volumio[15742]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 25 23:38:25 volumio-mf node[15742]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 25 23:38:25 volumio-mf volumio[15742]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 25 23:38:25 volumio-mf node[15742]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 25 23:38:25 volumio-mf volumio[15742]: *** WARNING *** For more information see Dec 25 23:38:25 volumio-mf node[15742]: *** WARNING *** For more information see Dec 25 23:38:25 volumio-mf volumio[15742]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 25 23:38:25 volumio-mf volumio[15742]: info: Discovery: Started advertising with name: Volumio-MF Dec 25 23:38:25 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 25 23:38:25 volumio-mf volumio[15742]: info: Loading plugin "spop"... Dec 25 23:38:26 volumio-mf volumio[15742]: info: Loading plugin "now_playing"... Dec 25 23:38:27 volumio-mf volumio[15742]: info: Loading plugin "outputs"... Dec 25 23:38:27 volumio-mf volumio[15742]: info: Loading plugin "albumart"... Dec 25 23:38:27 volumio-mf volumio[15742]: info: Plugin example_plugin is not enabled Dec 25 23:38:27 volumio-mf volumio[15742]: info: Loading plugin "inputs"... Dec 25 23:38:27 volumio-mf volumio[15742]: info: Loading plugin "updater_comm"... Dec 25 23:38:27 volumio-mf volumio[15742]: info: Plugin mpdemulation is not enabled Dec 25 23:38:27 volumio-mf volumio[15742]: info: Loading plugin "rest_api"... Dec 25 23:38:27 volumio-mf volumio[15742]: info: Loading plugin "websocket"... Dec 25 23:38:27 volumio-mf volumio[15742]: info: Starting Socket.io Server version 1.7.4 Dec 25 23:38:27 volumio-mf volumio[15742]: info: Loading plugin "backup_restore"... Dec 25 23:38:27 volumio-mf volumio[15834]: Forking 3 albumart workers Dec 25 23:38:27 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:27Z" level=trace msg="sent dealer ping" Dec 25 23:38:27 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:27Z" level=trace msg="received dealer pong" Dec 25 23:38:27 volumio-mf volumio[15846]: Starting albumart workers Dec 25 23:38:27 volumio-mf volumio[15742]: info: Applying required configuration parameters for plugin backup_restore Dec 25 23:38:27 volumio-mf volumio[15742]: info: Loading plugin "rpi_eeprom_config"... Dec 25 23:38:28 volumio-mf volumio[15845]: Starting albumart workers Dec 25 23:38:28 volumio-mf volumio[15844]: Starting albumart workers Dec 25 23:38:28 volumio-mf volumio[15742]: info: Applying required configuration parameters for plugin rpi_eeprom_config Dec 25 23:38:28 volumio-mf volumio[15742]: info: [RpiEepromConfig] Hardware capabilities loaded Dec 25 23:38:28 volumio-mf volumio[15742]: info: Loading plugin "rpi_eeprom_updater"... Dec 25 23:38:29 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:29Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 159" Dec 25 23:38:29 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:29Z" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Dec 25 23:38:29 volumio-mf volumio[15742]: info: Applying required configuration parameters for plugin rpi_eeprom_updater Dec 25 23:38:29 volumio-mf volumio[15742]: info: Loading plugin "scheduledrestart"... Dec 25 23:38:30 volumio-mf volumio[15742]: info: Applying required configuration parameters for plugin scheduledrestart Dec 25 23:38:31 volumio-mf volumio[15742]: info: Loading plugin "music_services_shield"... Dec 25 23:38:34 volumio-mf volumio[15742]: info: Applying required configuration parameters for plugin music_services_shield Dec 25 23:38:34 volumio-mf volumio[15742]: info: Loading plugin "Systeminfo"... Dec 25 23:38:36 volumio-mf volumio[15742]: info: Loading i18n strings for locale en Dec 25 23:38:36 volumio-mf volumio[15742]: Updating browse sources language Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::initPlayerControls Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 25 23:38:36 volumio-mf volumio[15742]: Express server listening on port 3000 Dec 25 23:38:36 volumio-mf volumio[15742]: [Metrics] WebUI: 23s 62.65ms Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreStateMachine::resetVolumioState Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreStateMachine::getcurrentVolume Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioRetrievevolume Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreStateMachine::pushState Dec 25 23:38:36 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 23:38:36 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioPushState Dec 25 23:38:36 volumio-mf volumio[15742]: info: Cannot mount NAS NAS_Music at system boot, trial number 2 ,retrying in 5 seconds Dec 25 23:38:37 volumio-mf volumio[15742]: info: Volumio Network Manager: Network status updated: 1 Dec 25 23:38:37 volumio-mf sudo[15918]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 25 23:38:37 volumio-mf sudo[15916]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 25 23:38:37 volumio-mf sudo[15918]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:37 volumio-mf sudo[15916]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:37 volumio-mf sudo[15916]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:37 volumio-mf sudo[15918]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:37 volumio-mf volumio[15742]: verbose: New Socket.io Connection to 192.168.1.8:3000 from 192.168.1.9 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Dec 25 23:38:38 volumio-mf volumio[15742]: verbose: New Socket.io Connection to 192.168.1.8:3000 from 192.168.1.9 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 25 23:38:38 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 25 23:38:38 volumio-mf volumio[15742]: info: Reloading queue from file Dec 25 23:38:38 volumio-mf volumio[15742]: info: Setting Device type: Raspberry PI Dec 25 23:38:38 volumio-mf volumio[15742]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 25 23:38:38 volumio-mf volumio[15742]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04171 Dec 25 23:38:38 volumio-mf volumio[15742]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 25 23:38:38 volumio-mf volumio[15742]: info: CoreStateMachine::setRepeat null single undefined Dec 25 23:38:38 volumio-mf volumio[15742]: info: CoreStateMachine::pushState Dec 25 23:38:38 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:38 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 23:38:38 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioPushState Dec 25 23:38:38 volumio-mf volumio[15742]: info: CoreStateMachine::setRandom null Dec 25 23:38:38 volumio-mf volumio[15742]: info: CoreStateMachine::pushState Dec 25 23:38:38 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:38 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioPushState Dec 25 23:38:38 volumio-mf volumio[15742]: info: Completed loading Core Plugins Dec 25 23:38:38 volumio-mf volumio[15742]: info: Preparing to generate the ALSA configuration file Dec 25 23:38:39 volumio-mf sudo[15932]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 25 23:38:39 volumio-mf sudo[15932]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:40 volumio-mf sudo[15932]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:41 volumio-mf volumio[15742]: info: Discovery: adding b4e06591-2c24-4720-8c44-6247a1e03709 Dec 25 23:38:41 volumio-mf volumio[15742]: info: Discovery: Found device Volumio-BW Dec 25 23:38:41 volumio-mf volumio[15742]: info: Discovery: Connecting to remote: 192.168.1.9 Dec 25 23:38:41 volumio-mf volumio[15742]: info: Discovery: adding 429a9283-8c22-4a73-bc09-9050462680b5 Dec 25 23:38:41 volumio-mf volumio[15742]: info: Discovery: Found device Volumio-MF Dec 25 23:38:41 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:38:41 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:41 volumio-mf volumio[15742]: Upnp client error: Error: This socket has been ended by the other party Dec 25 23:38:41 volumio-mf volumio[15742]: info: Upmpdcli Daemon Started Dec 25 23:38:41 volumio-mf volumio[15742]: info: Discovery: this is already registered, 429a9283-8c22-4a73-bc09-9050462680b5 Dec 25 23:38:41 volumio-mf volumio[15742]: info: Discovery: Found device Volumio-MF Dec 25 23:38:41 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:38:41 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:41 volumio-mf volumio[15742]: verbose: New Socket.io Connection to 192.168.1.8:3000 from 192.168.1.9 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 25 23:38:41 volumio-mf volumio[15742]: info: Cannot mount NAS NAS_Music at system boot, trial number 3 ,retrying in 5 seconds Dec 25 23:38:41 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Dec 25 23:38:41 volumio-mf volumio[15742]: info: Discovery: Connected to remote: 192.168.1.9 Dec 25 23:38:41 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:38:41 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:41 volumio-mf volumio[15742]: info: Asound.conf file written Dec 25 23:38:41 volumio-mf sudo[15953]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 25 23:38:41 volumio-mf sudo[15953]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:41 volumio-mf sudo[15953]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:42 volumio-mf volumio[15742]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 25 23:38:42 volumio-mf volumio[15742]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 25 23:38:42 volumio-mf volumio[15742]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Dec 25 23:38:42 volumio-mf volumio[15742]: info: Output device has changed, restarting MPD Dec 25 23:38:42 volumio-mf volumio[15742]: info: Output device has changed, restarting Shairport Sync Dec 25 23:38:42 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:42 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 25 23:38:42 volumio-mf sudo[15959]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 25 23:38:42 volumio-mf sudo[15962]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 25 23:38:42 volumio-mf sudo[15962]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:42 volumio-mf sudo[15959]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:42 volumio-mf sudo[15959]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:42 volumio-mf volumio[15742]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 25 23:38:42 volumio-mf volumio[15742]: info: ___________ START PLUGINS ___________ Dec 25 23:38:43 volumio-mf volumio[15742]: info: ControllerMpd::onStart: Initializing MPD Dec 25 23:38:43 volumio-mf volumio[15742]: info: Creating MPD Configuration file Dec 25 23:38:43 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 25 23:38:43 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 25 23:38:43 volumio-mf volumio[15742]: info: [1766705923085] CoreMusicLibrary::Adding element Media Servers Dec 25 23:38:43 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 25 23:38:43 volumio-mf volumio[15742]: info: UPNP Browser: Client initialized successfully Dec 25 23:38:43 volumio-mf sudo[15971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 25 23:38:43 volumio-mf sudo[15969]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 25 23:38:43 volumio-mf sudo[15971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:43 volumio-mf sudo[15969]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:43 volumio-mf sudo[15969]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:43 volumio-mf systemd[1]: musicservicesshield.service: Deactivated successfully. Dec 25 23:38:43 volumio-mf systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 25 23:38:43 volumio-mf systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 25 23:38:43 volumio-mf systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 25 23:38:43 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:43 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 25 23:38:44 volumio-mf volumio[15742]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 25 23:38:44 volumio-mf volumio[15742]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 25 23:38:44 volumio-mf volumio[15742]: info: [1766705924373] CoreMusicLibrary::Adding element Last_100 Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 25 23:38:44 volumio-mf volumio[15742]: info: [1766705924374] CoreMusicLibrary::Adding element Webradio Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 25 23:38:44 volumio-mf volumio[15742]: info: Initializing BBC Radios Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 25 23:38:44 volumio-mf volumio[15742]: info: Creating Spotify config file Dec 25 23:38:44 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:44 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:44Z" level=debug msg="handling play player command from c5c6ad81c2f6a0aa72de3875bf065ab9af1571d8" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=debug msg="resolved context of track" uri="spotify:album:2E5Jr8tcyqKrGzGPmNA3il" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=trace msg="fetched new page 0 with 18 items (list: 18)" uri="spotify:album:2E5Jr8tcyqKrGzGPmNA3il" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=warning msg="failed getting output device delay" error="ALSA error at snd_pcm_delay: Input/output error" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=debug msg="loading track (paused: false, position: 6ms)" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=trace msg="emitting websocket event: will_play" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=debug msg="selected format OGG_VORBIS_320 (ff450c12f479a0f4391cfe364dbd54e76ce82f53)" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=debug msg="requested aes key for file ff450c12f479a0f4391cfe364dbd54e76ce82f53, gid: 3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:45 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:45Z" level=trace msg="found 2 cdn urls" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=debug msg="fetched first chunk of 41, total size is 21476658 bytes" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=trace msg="seek to 6ms (diff: 6ms, samples: 264, bytes: 0)" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=info msg="loaded track \"Purple Rain\" (paused: false, position: 6ms, duration: 521866ms, prefetched: false)" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=warning msg="failed getting output device delay" error="ALSA error at snd_pcm_delay: Input/output error" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=trace msg="scheduling prefetch in 492s" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=trace msg="emitting websocket event: metadata" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=debug msg="sending successful reply for dealer request" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=debug msg="fetched chunk 1/40, size: 524288" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=debug msg="fetched chunk 2/40, size: 524288" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=debug msg="fetched chunk 3/40, size: 524288" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 23:38:46 volumio-mf go-librespot[1790]: time="2025-12-25T23:38:46Z" level=trace msg="emitting websocket event: playing" Dec 25 23:38:47 volumio-mf volumio[15742]: info: [now-playing] ConfigUpdater: config is up to date. Dec 25 23:38:47 volumio-mf volumio[15742]: info: [RpiEepromConfig] Starting Raspberry Pi EEPROM Configuration Manager Dec 25 23:38:47 volumio-mf volumio[15742]: info: [RpiEepromConfig] Detected full model string: Raspberry Pi 5 Model B Rev 1.1 Dec 25 23:38:47 volumio-mf volumio[15742]: info: [RpiEepromConfig] Matched to capability profile: Raspberry Pi 5 Dec 25 23:38:47 volumio-mf volumio[15742]: info: [RpiEepromConfig] Detected model: Raspberry Pi 5 Dec 25 23:38:47 volumio-mf volumio[15742]: info: [RpiEepromConfig] Boot modes: sd, usb, nvme Dec 25 23:38:47 volumio-mf volumio[15742]: info: [RpiEepromConfig] Using rpi-eeprom-config at: /usr/bin/rpi-eeprom-config Dec 25 23:38:47 volumio-mf volumio[15742]: info: [RpiEepromConfig] Backup directory ensured: /data/configuration/system_controller/rpi_eeprom_config/backup Dec 25 23:38:47 volumio-mf volumio[15742]: info: [RpiEepromConfig] Plugin started successfully Dec 25 23:38:48 volumio-mf volumio[15742]: info: [RpiEepromUpdater] Plugin started successfully Dec 25 23:38:49 volumio-mf volumio[15742]: info: Scheduling reboots with hours: 3, minutes: 0 in timezone: Europe/London Dec 25 23:38:49 volumio-mf volumio[15742]: info: Scheduling job with cron expression: 0 0 3 * * 0 Dec 25 23:38:49 volumio-mf volumio[15742]: info: Scheduling job with cron expression: 0 0 3 * * 1 Dec 25 23:38:49 volumio-mf volumio[15742]: info: Scheduling job with cron expression: 0 0 3 * * 2 Dec 25 23:38:49 volumio-mf volumio[15742]: info: Scheduling job with cron expression: 0 0 3 * * 3 Dec 25 23:38:49 volumio-mf volumio[15742]: info: Scheduling job with cron expression: 0 0 3 * * 4 Dec 25 23:38:49 volumio-mf volumio[15742]: info: Scheduling job with cron expression: 0 0 3 * * 5 Dec 25 23:38:49 volumio-mf volumio[15742]: info: Scheduling job with cron expression: 0 0 3 * * 6 Dec 25 23:38:50 volumio-mf volumio[15742]: info: Volumio Calling Home Dec 25 23:38:51 volumio-mf sudo[16048]: volumio : PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh Dec 25 23:38:51 volumio-mf sudo[16048]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:52 volumio-mf systemd[1]: mpd.service: Deactivated successfully. Dec 25 23:38:52 volumio-mf systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 25 23:38:52 volumio-mf systemd[1]: mpd.service: Consumed 4.684s CPU time. Dec 25 23:38:52 volumio-mf systemd[1]: mpd.socket: Deactivated successfully. Dec 25 23:38:52 volumio-mf systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 25 23:38:52 volumio-mf systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 25 23:38:52 volumio-mf systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 25 23:38:52 volumio-mf systemd[1]: Starting mpd.service - Music Player Daemon... Dec 25 23:38:53 volumio-mf sudo[16066]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 25 23:38:53 volumio-mf sudo[16066]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 25 23:38:53 volumio-mf sudo[16066]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:53 volumio-mf volumio-remote-updater[15831]: [819B blob data] Dec 25 23:38:54 volumio-mf volumio-remote-updater[15831]: downloading from http://updates2.volumio.org/pi/volumio/4.084/volumio_current.sqsh: Dec 25 23:38:54 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:54 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:54 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:54 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:54 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:54 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:54 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:54 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:54 volumio-mf volumio[15742]: info: [now-playing] App is listening on port 4004. Dec 25 23:38:54 volumio-mf volumio[15742]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Dec 25 23:38:54 volumio-mf volumio[15742]: info: Cannot mount NAS NAS_Music at system boot, trial number 4 ,retrying in 5 seconds Dec 25 23:38:54 volumio-mf volumio[15742]: info: MPD Permissions set Dec 25 23:38:54 volumio-mf volumio[15742]: info: MPD Permissions set Dec 25 23:38:54 volumio-mf volumio[15742]: verbose: New Socket.io Connection to 192.168.1.8:3000 from 192.168.1.43 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Dec 25 23:38:54 volumio-mf volumio[15742]: info: Spotify config file written Dec 25 23:38:54 volumio-mf volumio[15742]: verbose: New Socket.io Connection to 192.168.1.8 from 192.168.1.43 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 5 Dec 25 23:38:54 volumio-mf volumio[15742]: info: Volumio called home Dec 25 23:38:54 volumio-mf volumio[15742]: info: No need to fix Spotify hosts Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf sudo[16087]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf sudo[16087]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 25 23:38:54 volumio-mf systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 25 23:38:54 volumio-mf systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 25 23:38:54 volumio-mf systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 25 23:38:54 volumio-mf systemd[1]: go-librespot-daemon.service: Consumed 2min 53.889s CPU time. Dec 25 23:38:54 volumio-mf systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 25 23:38:54 volumio-mf go-librespot[16099]: go-librespot daemon starting... Dec 25 23:38:54 volumio-mf sudo[16087]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:54 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:54Z" level=info msg="running go-librespot 0.4.0" Dec 25 23:38:54 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:54Z" level=debug msg="app state loaded" Dec 25 23:38:54 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:54Z" level=info msg="api server listening on 127.0.0.1:9879" Dec 25 23:38:54 volumio-mf volumio[15742]: verbose: New Socket.io Connection to 192.168.1.8 from 192.168.1.43 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 6 Dec 25 23:38:54 volumio-mf volumio[15742]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 25 23:38:54 volumio-mf volumio[15742]: info: Starting Shairport Sync Dec 25 23:38:54 volumio-mf volumio[15742]: info: Starting Shairport Sync Dec 25 23:38:54 volumio-mf volumio[15742]: info: Starting Shairport Sync Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 23:38:54 volumio-mf volumio[15742]: info: Discovery: Getting this device information Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:38:54 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 23:38:54 volumio-mf sudo[16110]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 25 23:38:54 volumio-mf sudo[16110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:54 volumio-mf sudo[16114]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 25 23:38:54 volumio-mf sudo[16114]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:54 volumio-mf sudo[16112]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 25 23:38:54 volumio-mf sudo[16112]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:54 volumio-mf systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 25 23:38:54 volumio-mf systemd[1]: shairport-sync.service: Deactivated successfully. Dec 25 23:38:54 volumio-mf systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 25 23:38:54 volumio-mf systemd[1]: shairport-sync.service: Consumed 17.990s CPU time. Dec 25 23:38:54 volumio-mf sudo[16048]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:54 volumio-mf systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 25 23:38:54 volumio-mf sudo[16110]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:54 volumio-mf sudo[16112]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:54 volumio-mf sudo[16114]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:54 volumio-mf volumio[15742]: info: Shairport-Sync Started Dec 25 23:38:54 volumio-mf volumio[15742]: Error adding Membership: Error: addMembership EINVAL Dec 25 23:38:54 volumio-mf volumio[15742]: info: Shairport-Sync Started Dec 25 23:38:54 volumio-mf volumio[15742]: info: Shairport-Sync Started Dec 25 23:38:54 volumio-mf sudo[16121]: volumio : PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh Dec 25 23:38:54 volumio-mf sudo[16121]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 23:38:54 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:38:54 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:55 volumio-mf volumio-remote-updater[986]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:55 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:55 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:55 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:55 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:55 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:55 volumio-mf volumio[15742]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 25 23:38:55 volumio-mf volumio[15742]: SPOTIFY: BQAT7uazrHv51vVtwhmpO0UuyBeRWGXFPS_el9ESeq28iWb1HdXlBDZskmwc3jZr4XfT_7yvkA1FpBqJykRyW4la-zw7vNtsn6eddzaei9Sww4ZFE85PqkjngyVZDzKiMxXCZ8zYdhOoLmlPARkajzRjO6mnFftK-KbHoNsxMG-X_X3SE7fAg3Ea0M7Dew_E2gqdc7LLCsVjKtSb4Y70N7clf6kKH0n_xGXiW8lHwZQnmI0zwZNn8Nx913Emv0VRoaYAkWIUyMilWkjNmUy4p8AM8kzWDuvY Dec 25 23:38:55 volumio-mf volumio[15742]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 25 23:38:55 volumio-mf volumio[15742]: info: New Spotify access token = BQAT7uazrHv51vVtwhmpO0UuyBeRWGXFPS_el9ESeq28iWb1HdXlBDZskmwc3jZr4XfT_7yvkA1FpBqJykRyW4la-zw7vNtsn6eddzaei9Sww4ZFE85PqkjngyVZDzKiMxXCZ8zYdhOoLmlPARkajzRjO6mnFftK-KbHoNsxMG-X_X3SE7fAg3Ea0M7Dew_E2gqdc7LLCsVjKtSb4Y70N7clf6kKH0n_xGXiW8lHwZQnmI0zwZNn8Nx913Emv0VRoaYAkWIUyMilWkjNmUy4p8AM8kzWDuvY Dec 25 23:38:55 volumio-mf volumio[15742]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 25 23:38:55 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:55Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 25 23:38:55 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:55Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 25 23:38:55 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:55Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 25 23:38:55 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:55Z" level=info msg="zeroconf server listening on port 45139" Dec 25 23:38:55 volumio-mf volumio[15742]: SPOTIFY: User informations: {"country":"GB","display_name":"dharmos","email":"receipt-sdd@datta.org.uk","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/dharmos"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/dharmos","id":"dharmos","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85b3845ba5c80593e7e81633a1","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82b3845ba5c80593e7e81633a1","width":64}],"product":"premium","type":"user","uri":"spotify:user:dharmos"} Dec 25 23:38:55 volumio-mf volumio[15742]: info: Spotify Successfully logged in Dec 25 23:38:55 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 25 23:38:55 volumio-mf volumio[15742]: info: [1766705935452] CoreMusicLibrary::Adding element Spotify Dec 25 23:38:55 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 25 23:38:55 volumio-mf volumio[15742]: Cannot find translation for source Spotify Dec 25 23:38:55 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:55Z" level=debug msg="obtained new client token: AABt5DuGnBPCZ91moDPLPNdycx8P7SOAf1R43j/uP/LGfxryRSI5c7vabfyUZ/+2KSRj0cMOwY6tnb5mH66U8lExJ6ZRBB52f5rzIN3tpJsZJbO5g3re3T+QG1s6BmaFQxn/kSZOrn1w8qBtwIwFK7Qjhi71zuWLMQcwy7zdH5nBKTF+SjjAbvpFZ798GJdHAonoDrOEDd3hMjSLhmmas5ndIcWkwg8yshvlFJYF6xMvGK/zNnUKC5yUL20=" Dec 25 23:38:55 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:55Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 25 23:38:55 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:55Z" level=debug msg="completed keyexchange" Dec 25 23:38:55 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:55Z" level=debug msg="completed challenge" Dec 25 23:38:56 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:56 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:56 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:56 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:56 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:56 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:56 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:56Z" level=info msg="authenticated AP" username="dh***os" Dec 25 23:38:56 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:56Z" level=info msg="authenticated Login5" username="dh***os" Dec 25 23:38:56 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:56Z" level=debug msg="initializing zeroconf session" username="dh***os" Dec 25 23:38:57 volumio-mf volumio-remote-updater[986]: PROGRESS: 38, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:57 volumio-mf volumio-remote-updater[986]: PROGRESS: 47, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:57 volumio-mf volumio-remote-updater[986]: PROGRESS: 47, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:57 volumio-mf volumio-remote-updater[986]: PROGRESS: 47, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:57 volumio-mf volumio-remote-updater[986]: PROGRESS: 47, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:57 volumio-mf volumio-remote-updater[986]: PROGRESS: 47, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="dealer connection opened" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=trace msg="starting accesspoint recv loop" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=trace msg="starting dealer recv loop" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=trace msg="received accesspoint ping" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="received connection id: ZWRkYzcxNTctZGIx...Rjk1ODIyMEI1Qw==" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=trace msg="received accesspoint pong ack" Dec 25 23:38:57 volumio-mf mpd[16078]: 2025-12-25T23:38:57 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 25 23:38:57 volumio-mf systemd[1]: Started mpd.service - Music Player Daemon. Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="put connect state because NEW_DEVICE" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="update volume requested to 65535/65535" Dec 25 23:38:57 volumio-mf sudo[15962]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:57 volumio-mf sudo[15971]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:57 volumio-mf systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 25 23:38:57 volumio-mf volumio[15742]: info: Completed starting Core Plugins Dec 25 23:38:57 volumio-mf volumio[15742]: info: ------------------------------------------- Dec 25 23:38:57 volumio-mf volumio[15742]: info: ----- MyVolumio plugins startup ---- Dec 25 23:38:57 volumio-mf volumio[15742]: info: ------------------------------------------- Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=debug msg="put connect state because VOLUME_CHANGED" Dec 25 23:38:57 volumio-mf go-librespot[16101]: time="2025-12-25T23:38:57Z" level=trace msg="emitting websocket event: volume" Dec 25 23:38:57 volumio-mf volumio[15742]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 25 23:38:57 volumio-mf volumio[15742]: info: MPD running with PID16078 Dec 25 23:38:57 volumio-mf volumio[15742]: ,establishing connection Dec 25 23:38:57 volumio-mf volumio[15742]: info: go-librespot daemon successfully initialized Dec 25 23:38:58 volumio-mf volumio-remote-updater[986]: PROGRESS: 47, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:58 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:58 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:58 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:58 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:58 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:58 volumio-mf volumio[15742]: error: MPD error: The expression evaluated to a falsy value: Dec 25 23:38:58 volumio-mf volumio[15742]: assert.ok(self.idling) Dec 25 23:38:58 volumio-mf volumio[15742]: error: The expression evaluated to a falsy value: Dec 25 23:38:58 volumio-mf volumio[15742]: assert.ok(self.idling) Dec 25 23:38:58 volumio-mf volumio[15742]: error: MPD error: The expression evaluated to a falsy value: Dec 25 23:38:58 volumio-mf volumio[15742]: assert.ok(self.idling) Dec 25 23:38:58 volumio-mf volumio[15742]: error: The expression evaluated to a falsy value: Dec 25 23:38:58 volumio-mf volumio[15742]: assert.ok(self.idling) Dec 25 23:38:58 volumio-mf volumio[15742]: verbose: New Socket.io Connection to 192.168.1.8 from 192.168.1.43 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Dec 25 23:38:58 volumio-mf volumio[15742]: error: updateQueue error: null Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetVisibleSources Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:38:58 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 25 23:38:58 volumio-mf volumio[15742]: info: Received Get System Info Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 23:38:58 volumio-mf volumio[15742]: info: Discovery: Getting this device information Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:38:58 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 23:38:58 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:38:58 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:38:58 volumio-mf volumio[15742]: info: Listing playlists Dec 25 23:38:58 volumio-mf bash[16163]: cset: --> shielding system active with Dec 25 23:38:58 volumio-mf bash[16163]: cset: "system" cpuset of CPUSPEC(0-1) with 187 tasks running Dec 25 23:38:58 volumio-mf bash[16163]: cset: "user" cpuset of CPUSPEC(2-3) with 3 tasks running Dec 25 23:38:58 volumio-mf systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 25 23:38:58 volumio-mf systemd[1]: Reloading. Dec 25 23:38:59 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:59 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:59 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:59 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:59 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:59 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:38:59 volumio-mf volumio[15742]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Dec 25 23:38:59 volumio-mf systemd[1]: /etc/systemd/system/musicservicesshield.service:14: Failed to parse output specifier, ignoring: jouurnal Dec 25 23:38:59 volumio-mf systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 25 23:38:59 volumio-mf systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 25 23:38:59 volumio-mf systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 25 23:38:59 volumio-mf systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 25 23:38:59 volumio-mf sudo[16121]: pam_unix(sudo:session): session closed for user root Dec 25 23:38:59 volumio-mf volumio[15742]: info: succeeded Dec 25 23:39:00 volumio-mf volumio-remote-updater[986]: PROGRESS: 55, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:00 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:00 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:00 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:00 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:00 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=debug msg="handling transfer player command from c5c6ad81c2f6a0aa72de3875bf065ab9af1571d8" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=debug msg="resolved context of track" uri="spotify:album:2E5Jr8tcyqKrGzGPmNA3il" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=trace msg="fetched new page 0 with 18 items (list: 18)" uri="spotify:album:2E5Jr8tcyqKrGzGPmNA3il" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=debug msg="loading track (paused: false, position: 14192ms)" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=trace msg="emitting websocket event: will_play" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=debug msg="selected format OGG_VORBIS_320 (ff450c12f479a0f4391cfe364dbd54e76ce82f53)" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=debug msg="requested aes key for file ff450c12f479a0f4391cfe364dbd54e76ce82f53, gid: 3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:00 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:00Z" level=trace msg="found 2 cdn urls" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:00 volumio-mf volumio[15742]: info: Initializing connection to go-librespot Websocket Dec 25 23:39:01 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:01 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:01 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:01 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:01 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:01 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=debug msg="new websocket client" Dec 25 23:39:01 volumio-mf volumio[15742]: info: Connection to go-librespot Websocket established Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=debug msg="fetched first chunk of 41, total size is 21476658 bytes" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=trace msg="seek to 14192ms (diff: 324ms, samples: 625867, bytes: 476562)" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=debug msg="created new output device" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 371519 us, period size = 16384 frames, buffer time = 1486077 us, buffer size = 65536 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=info msg="loaded track \"Purple Rain\" (paused: false, position: 14192ms, duration: 521866ms, prefetched: false)" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=debug msg="fetched chunk 1/40, size: 524288" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=trace msg="scheduling prefetch in 478s" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=trace msg="emitting websocket event: metadata" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=trace msg="emitting websocket event: active" Dec 25 23:39:01 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:01Z" level=debug msg="sending successful reply for dealer request" Dec 25 23:39:01 volumio-mf volumio[15742]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3NcpMHbTZx2GNb3CbTzR6h","name":"Purple Rain","artist_names":["Prince"],"album_name":"The Hits 2","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026a8bceb9f636d63a6df6ef9f","position":14192,"duration":521866,"release_date":"year:1993 month:9 day:10","track_number":18,"disc_number":1}} Dec 25 23:39:01 volumio-mf volumio[15742]: SPOTIFY: received: {"type":"active","data":null} Dec 25 23:39:01 volumio-mf volumio[15742]: info: Aligning Spotify Volume to Volumio Volume Dec 25 23:39:01 volumio-mf volumio[15742]: info: CoreCommandRouter::volumioGetState Dec 25 23:39:01 volumio-mf volumio[15742]: info: CorePlayQueue::getTrack 0 Dec 25 23:39:02 volumio-mf volumio-remote-updater[986]: PROGRESS: 63, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:02 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:02 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:02 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:02 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:02 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:02 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:02Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 23:39:02 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:02Z" level=trace msg="emitting websocket event: playing" Dec 25 23:39:02 volumio-mf volumio[15742]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:album:2E5Jr8tcyqKrGzGPmNA3il","uri":"spotify:track:3NcpMHbTZx2GNb3CbTzR6h","resume":false,"play_origin":"album"}} Dec 25 23:39:02 volumio-mf volumio[15742]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 25 23:39:02 volumio-mf volumio[15742]: TypeError: Cannot read properties of undefined (reading 'service') Dec 25 23:39:02 volumio-mf volumio[15742]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 25 23:39:02 volumio-mf volumio[15742]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Dec 25 23:39:02 volumio-mf volumio[15742]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 25 23:39:02 volumio-mf volumio[15742]: at WebSocket.emit (node:events:514:28) Dec 25 23:39:02 volumio-mf volumio[15742]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 25 23:39:02 volumio-mf volumio[15742]: at Receiver.emit (node:events:514:28) Dec 25 23:39:02 volumio-mf volumio[15742]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 25 23:39:02 volumio-mf volumio[15742]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 25 23:39:02 volumio-mf volumio[15742]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 25 23:39:02 volumio-mf volumio[15742]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 25 23:39:02 volumio-mf volumio[15742]: at writeOrBuffer (node:internal/streams/writable:399:12) Dec 25 23:39:02 volumio-mf volumio[15742]: at _write (node:internal/streams/writable:340:10) Dec 25 23:39:02 volumio-mf volumio[15742]: at Writable.write (node:internal/streams/writable:344:10) Dec 25 23:39:02 volumio-mf volumio[15742]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 25 23:39:02 volumio-mf volumio[15742]: at Socket.emit (node:events:514:28) Dec 25 23:39:02 volumio-mf volumio[15742]: at addChunk (node:internal/streams/readable:343:12) Dec 25 23:39:02 volumio-mf volumio[15742]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 25 23:39:02 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:02Z" level=debug msg="fetched chunk 3/40, size: 524288" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:02 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:02Z" level=debug msg="fetched chunk 2/40, size: 524288" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:02 volumio-mf go-librespot[16101]: time="2025-12-25T23:39:02Z" level=debug msg="fetched chunk 4/40, size: 524288" uri="spotify:track:3NcpMHbTZx2GNb3CbTzR6h" Dec 25 23:39:03 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:03 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:03 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:03 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:03 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:03 volumio-mf volumio-remote-updater[986]: PROGRESS: 72, STATUS: "Downloading new update", ETA: "4m" Dec 25 23:39:03 volumio-mf sudo[16200]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-25 23:38' Dec 25 23:39:03 volumio-mf sudo[16200]: 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="5250573efb99f2852fa27ea7e92def8586093039" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="d9e2b6784b9276d5a676bf564ce7524ad160509b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 19 15:53:15 UTC 2025" VOLUMIO_VERSION="4.082" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="47d7740e8c55792fe06a847eb7ad6b29"