vm-test-run-nixos-test-k3s
checks.aarch64-linux.nixos-test-k3s
· build #363
· raw
1tribuchet: building on eliza2Machine state will be reset. To keep it, pass --keep-machine-state3start all VLans4(finished: start all VLans, in 0.00 seconds)5Test will time out and terminate in 3600.0 seconds6run the VM test script7machine: waiting for unit k3s.service8machine: waiting for the VM to finish booting9machine: starting vm10machine: QEMU running (pid 45)11machine # Disk image does not exist, creating the virtualisation disk image...12machine # Formatting '/build/vm-state-machine/tmp.qDnb6kTTdQ', fmt=raw size=858993459213machine # mke2fs 1.47.4 (6-Mar-2025)14machine # Discarding device blocks: 0/2097152 done15machine # Creating filesystem with 2097152 4k blocks and 524288 inodes16machine # Filesystem UUID: a75c17f9-9e0f-4894-ad5a-aadd76e87b1717machine # Superblock backups stored on blocks:18machine # 32768, 98304, 163840, 229376, 294912, 819200, 884736, 160563219machine # 20machine # Allocating group tables: 0/64 done21machine # Writing inode tables: 0/64 done22machine # Creating journal (16384 blocks): done23machine # Writing superblocks and filesystem accounting information: 0/64 done24machine # 25machine # Virtualisation disk image created.26machine # Starting virtiofs daemons...27machine # [2026-10-06T09:19:31Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)28machine # [2026-10-06T09:19:31Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)29machine # [2026-10-06T09:19:31Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether30machine # [2026-10-06T09:19:31Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)31machine # [2026-10-06T09:19:31Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether32machine # [2026-10-06T09:19:31Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether33machine # [2026-10-06T09:19:31Z INFO virtiofsd] Waiting for vhost-user socket connection...34machine # [2026-10-06T09:19:31Z INFO virtiofsd] Waiting for vhost-user socket connection...35machine # [2026-10-06T09:19:31Z INFO virtiofsd] Waiting for vhost-user socket connection...36machine # [2026-10-06T09:19:31Z INFO virtiofsd] Client connected, servicing requests37machine # [2026-10-06T09:19:31Z INFO virtiofsd] Client connected, servicing requests38machine # [2026-10-06T09:19:31Z INFO virtiofsd] Client connected, servicing requests39machine # [ 0.000000] Booting Linux on physical CPU 0x0000000000 [0xc00fac40]40machine # [ 0.000000] Linux version 6.18.54 (nixbld@localhost) (gcc (GCC) 16.2.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT Fri Sep 25 14:35:54 UTC 202641machine # [ 0.000000] KASLR enabled42machine # [ 0.000000] random: crng init done43machine # [ 0.000000] Machine model: linux,dummy-virt44machine # [ 0.000000] efi: UEFI not found.45machine # [ 0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT46machine # [ 0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000ffffffff]47machine # [ 0.000000] NODE_DATA(0) allocated [mem 0xffdec0c0-0xffdef83f]48machine # [ 0.000000] Zone ranges:49machine # [ 0.000000] DMA [mem 0x0000000040000000-0x00000000ffffffff]50machine # [ 0.000000] DMA32 empty51machine # [ 0.000000] Normal empty52machine # [ 0.000000] Device empty53machine # [ 0.000000] Movable zone start for each node54machine # [ 0.000000] Early memory node ranges55machine # [ 0.000000] node 0: [mem 0x0000000040000000-0x00000000ffffffff]56machine # [ 0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000ffffffff]57machine # [ 0.000000] cma: Reserved 32 MiB at 0x00000000fac0000058machine # [ 0.000000] psci: probing for conduit method from DT.59machine # [ 0.000000] psci: PSCIv1.3 detected in firmware.60machine # [ 0.000000] psci: Using standard PSCI v0.2 function IDs61machine # [ 0.000000] psci: Trusted OS migration not required62machine # [ 0.000000] psci: SMC Calling Convention v1.163machine # [ 0.000000] smccc: KVM: hypervisor services detected (0x00000000 0x00000000 0x00000000 0x00000003)64machine # [ 0.000000] percpu: Embedded 76 pages/cpu s186776 r8192 d116328 u31129665machine # [ 0.000000] Detected PIPT I-cache on CPU066machine # [ 0.000000] CPU features: detected: Address authentication (architected QARMA5 algorithm)67machine # [ 0.000000] CPU features: detected: GICv3 CPU interface68machine # [ 0.000000] CPU features: detected: Spectre-v469machine # [ 0.000000] CPU features: detected: Spectre-BHB70machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC03_CPU_3871machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC04_CPU_2372machine # [ 0.000000] alternatives: applying boot alternatives73machine # [ 0.000000] Kernel command line: console=ttyAMA0 console=tty0 panic=1 boot.panic_on_fail clocksource=acpi_pm root=fstab loglevel=7 net.ifnames=0 lsm=landlock,yama,bpf init=/nix/store/sb3qmfpvc24zwlmnr17fywvj0v0p7fbh-nixos-system-machine-test/init regInfo=/nix/.ro-store/b3sin254gb2pii5x12llfmli87mj39id-closure-info/registration console=ttyAMA0,115200n8 console=tty074machine # [ 0.000000] Unknown kernel command line parameters "regInfo=/nix/.ro-store/b3sin254gb2pii5x12llfmli87mj39id-closure-info/registration", will be passed to user space.75machine # [ 0.000000] printk: log buffer data + meta data: 131072 + 458752 = 589824 bytes76machine # [ 0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)77machine # [ 0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)78machine # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size adjusted to 3MB79machine # [ 0.000000] software IO TLB: area num 2.80machine # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size roundup to 4MB81machine # [ 0.000000] software IO TLB: mapped [mem 0x00000000fa200000-0x00000000fa600000] (4MB)82machine # [ 0.000000] Fallback order for Node 0: 083machine # [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 78643284machine # [ 0.000000] Policy zone: DMA85machine # [ 0.000000] mem auto-init: stack:all(zero), heap alloc:on, heap free:off86machine # [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=187machine # [ 0.000000] allocated 6291456 bytes of page_ext88machine # [ 0.000000] ftrace: allocating 75026 entries in 294 pages89machine # [ 0.000000] ftrace: allocated 294 pages with 4 groups90machine # [ 0.000000] rcu: Hierarchical RCU implementation.91machine # [ 0.000000] rcu: RCU event tracing is enabled.92machine # [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=2.93machine # [ 0.000000] Trampoline variant of Tasks RCU enabled.94machine # [ 0.000000] Rude variant of Tasks RCU enabled.95machine # [ 0.000000] Tracing variant of Tasks RCU enabled.96machine # [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.97machine # [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=298machine # [ 0.000000] RCU Tasks: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.99machine # [ 0.000000] RCU Tasks Rude: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.100machine # [ 0.000000] RCU Tasks Trace: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.101machine # [ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0102machine # [ 0.000000] GICv3: 256 SPIs implemented103machine # [ 0.000000] GICv3: 0 Extended SPIs implemented104machine # [ 0.000000] Root IRQ handler: gic_handle_irq105machine # [ 0.000000] GICv3: GICv3 features: 16 PPIs, DirectLPI106machine # [ 0.000000] GICv3: GICD_CTLR.DS=1, SCR_EL3.FIQ=0107machine # [ 0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a0000108machine # [ 0.000000] ITS [mem 0x08080000-0x0809ffff]109machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Devices @45100000 (indirect, esz 8, psz 64K, shr 1)110machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @45110000 (flat, esz 8, psz 64K, shr 1)111machine # [ 0.000000] GICv3: using LPI property table @0x0000000045130000112machine # [ 0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000045140000113machine # [ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.114machine # [ 0.000000] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns115machine # [ 0.000000] arch_timer: cp15 timer running at 1000.00MHz (virt).116machine # [ 0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns117machine # [ 0.000000] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns118machine # [ 0.000049] arm-pv: using stolen time PV119machine # [ 0.001258] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)120machine # [ 0.001481] Console: colour dummy device 80x25121machine # [ 0.001489] printk: legacy console [tty0] enabled122machine # [ 0.001697] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000)123machine # [ 0.001705] pid_max: default: 32768 minimum: 301124machine # [ 0.001778] LSM: initializing lsm=capability,landlock,yama,bpf,ima125machine # [ 0.002051] landlock: Up and running.126machine # [ 0.002054] Yama: becoming mindful.127machine # [ 0.003244] LSM support for eBPF active128machine # [ 0.003514] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)129machine # [ 0.003582] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)130machine # [ 0.005687] rcu: Hierarchical SRCU implementation.131machine # [ 0.005693] rcu: Max phase no-delay instances is 1000.132machine # [ 0.005867] Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level133machine # [ 0.007261] fsl-mc MSI: its@8080000 domain created134machine # [ 0.007387] EFI services will not be available.135machine # [ 0.007515] smp: Bringing up secondary CPUs ...136machine # [ 0.008162] Detected PIPT I-cache on CPU1137machine # [ 0.008228] GICv3: CPU1: found redistributor 1 region 0:0x00000000080c0000138machine # [ 0.008310] GICv3: CPU1: using allocated LPI pending table @0x0000000045150000139machine # [ 0.008388] CPU1: Booted secondary processor 0x0000000001 [0xc00fac40]140machine # [ 0.008760] smp: Brought up 1 node, 2 CPUs141machine # [ 0.008774] SMP: Total of 2 processors activated.142machine # [ 0.008777] CPU: All CPU(s) started at EL1143machine # [ 0.008786] CPU features: detected: Branch Target Identification144machine # [ 0.008790] CPU features: detected: ARMv8.4 Translation Table Level145machine # [ 0.008792] CPU features: detected: Instruction cache invalidation not required for I/D coherence146machine # [ 0.008796] CPU features: detected: Data cache clean to the PoU not required for I/D coherence147machine # [ 0.008799] CPU features: detected: Common not Private translations148machine # [ 0.008802] CPU features: detected: CRC32 instructions149machine # [ 0.008805] CPU features: detected: Data cache clean to Point of Deep Persistence150machine # [ 0.008808] CPU features: detected: Data cache clean to Point of Persistence151machine # [ 0.008811] CPU features: detected: Data independent timing control (DIT)152machine # [ 0.008814] CPU features: detected: E0PD153machine # [ 0.008816] CPU features: detected: Enhanced Counter Virtualization154machine # [ 0.008818] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF)155machine # [ 0.008822] CPU features: detected: Enhanced Virtualization Traps156machine # [ 0.008824] CPU features: detected: Fine Grained Traps157machine # [ 0.008827] CPU features: detected: Generic authentication (architected QARMA5 algorithm)158machine # [ 0.008831] CPU features: detected: RCpc load-acquire (LDAPR)159machine # [ 0.008834] CPU features: detected: LSE atomic instructions160machine # [ 0.008836] CPU features: detected: Privileged Access Never161machine # [ 0.008839] CPU features: detected: PMUv3162machine # [ 0.008841] CPU features: detected: RAS Extension Support163machine # [ 0.008843] CPU features: detected: RASv1p1 Extension Support164machine # [ 0.008846] CPU features: detected: Random Number Generator165machine # [ 0.008848] CPU features: detected: Speculation barrier (SB)166machine # [ 0.008851] CPU features: detected: Stage-2 Force Write-Back167machine # [ 0.008853] CPU features: detected: TLB range maintenance instructions168machine # [ 0.008857] CPU features: detected: Speculative Store Bypassing Safe (SSBS)169machine # [ 0.008942] alternatives: applying system-wide alternatives170machine # [ 0.011936] CPU features: detected: BBM Level 2 without TLB conflict abort171machine # [ 0.012230] Memory: 2944132K/3145728K available (24512K kernel code, 7094K rwdata, 26568K rodata, 4736K init, 1106K bss, 154920K reserved, 32768K cma-reserved)172machine # [ 0.013268] devtmpfs: initialized173machine # [ 0.015910] posixtimers hash table entries: 1024 (order: 2, 16384 bytes, linear)174machine # [ 0.015950] futex hash table entries: 512 (32768 bytes on 1 NUMA nodes, total 32 KiB, linear).175machine # [ 0.016174] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL176machine # [ 0.016179] 0 pages in range for non-PLT usage177machine # [ 0.016180] 508208 pages in range for PLT usage178machine # [ 0.016310] pinctrl core: initialized pinctrl subsystem179machine # [ 0.017226] DMI not present or invalid.180machine # [ 0.022103] NET: Registered PF_NETLINK/PF_ROUTE protocol family181machine # [ 0.024771] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations182machine # [ 0.025072] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations183machine # [ 0.025384] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations184machine # [ 0.025411] audit: initializing netlink subsys (disabled)185machine # [ 0.025903] audit: type=2000 audit(0.024:1): state=initialized audit_enabled=0 res=1186machine # [ 0.027300] thermal_sys: Registered thermal governor 'fair_share'187machine # [ 0.027306] thermal_sys: Registered thermal governor 'bang_bang'188machine # [ 0.027315] thermal_sys: Registered thermal governor 'step_wise'189machine # [ 0.027319] thermal_sys: Registered thermal governor 'user_space'190machine # [ 0.027323] thermal_sys: Registered thermal governor 'power_allocator'191machine # [ 0.027406] cpuidle: using governor ladder192machine # [ 0.027432] cpuidle: using governor menu193machine # [ 0.027955] hw-breakpoint: found 16 breakpoint and 4 watchpoint registers.194machine # [ 0.028016] ASID allocator initialised with 65536 entries195machine # [ 0.030292] Serial: AMBA PL011 UART driver196machine # [ 0.040449] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 13, base_baud = 0) is a PL011 rev1197machine # [ 0.040736] printk: console [ttyAMA0] enabled198machine # [ 0.068483] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages199machine # [ 0.068493] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page200machine # [ 0.068497] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages201machine # [ 0.068500] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page202machine # [ 0.068503] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages203machine # [ 0.068506] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page204machine # [ 0.068509] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages205machine # [ 0.068512] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page206machine # [ 0.089551] fbcon: Taking over console207machine # [ 0.089567] ACPI: Interpreter disabled.208machine # [ 0.092653] iommu: Default domain type: Translated209machine # [ 0.092661] iommu: DMA domain TLB invalidation policy: strict mode210machine # [ 0.093552] SCSI subsystem initialized211machine # [ 0.096921] usbcore: registered new interface driver usbfs212machine # [ 0.097008] usbcore: registered new interface driver hub213machine # [ 0.097035] usbcore: registered new device driver usb214machine # [ 0.097443] pps_core: LinuxPPS API ver. 1 registered215machine # [ 0.097447] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>216machine # [ 0.097458] PTP clock support registered217machine # [ 0.097509] EDAC MC: Ver: 3.0.0218machine # [ 0.100819] scmi_core: SCMI protocol bus registered219machine # [ 0.101533] FPGA manager framework220machine # [ 0.102307] vgaarb: loaded221machine # [ 0.103530] clocksource: Switched to clocksource arch_sys_counter222machine # [ 0.104374] VFS: Disk quotas dquot_6.6.0223machine # [ 0.104410] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)224machine # [ 0.108076] netfs: FS-Cache loaded225machine # [ 0.108298] pnp: PnP ACPI: disabled226machine # [ 0.112486] NET: Registered PF_INET protocol family227machine # [ 0.113125] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)228machine # [ 0.143504] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)229machine # [ 0.143682] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)230machine # [ 0.143722] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)231machine # [ 0.143864] TCP bind hash table entries: 32768 (order: 8, 1048576 bytes, linear)232machine # [ 0.144143] TCP: Hash tables configured (established 32768 bind 32768)233machine # [ 0.144252] MPTCP token hash table entries: 4096 (order: 5, 98304 bytes, linear)234machine # [ 0.144298] UDP hash table entries: 2048 (order: 5, 131072 bytes, linear)235machine # [ 0.144358] UDP-Lite hash table entries: 2048 (order: 5, 131072 bytes, linear)236machine # [ 0.144496] NET: Registered PF_UNIX/PF_LOCAL protocol family237machine # [ 0.144523] NET: Registered PF_XDP protocol family238machine # [ 0.144542] PCI: CLS 0 bytes, default 64239machine # [ 0.144843] Trying to unpack rootfs image as initramfs...240machine # [ 0.151617] kvm [1]: HYP mode not available241machine # [ 0.234667] Initialise system trusted keyrings242machine # [ 0.236252] workingset: timestamp_bits=42 max_order=20 bucket_order=0243machine # [ 0.236643] squashfs: version 4.0 (2009/01/31) Phillip Lougher244machine # [ 0.236712] 9p: Installing v9fs 9p2000 file system support245machine # [ 0.251169] Key type asymmetric registered246machine # [ 0.251175] Asymmetric key parser 'x509' registered247machine # [ 0.251232] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 242)248machine # [ 0.253719] io scheduler mq-deadline registered249machine # [ 0.253724] io scheduler kyber registered250machine # [ 0.263639] pl061_gpio 9030000.pl061: PL061 GPIO chip registered251machine # [ 0.271587] ledtrig-cpu: registered to indicate activity on CPUs252machine # [ 0.272085] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:253machine # [ 0.272102] pci-host-generic 4010000000.pcie: IO 0x003eff0000..0x003effffff -> 0x0000000000254machine # [ 0.272113] pci-host-generic 4010000000.pcie: MEM 0x0010000000..0x003efeffff -> 0x0010000000255machine # [ 0.272119] pci-host-generic 4010000000.pcie: MEM 0x8000000000..0xffffffffff -> 0x8000000000256machine # [ 0.272140] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits257machine # [ 0.272166] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]258machine # [ 0.272254] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00259machine # [ 0.272261] pci_bus 0000:00: root bus resource [bus 00-ff]260machine # [ 0.272266] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]261machine # [ 0.272269] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]262machine # [ 0.272272] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]263machine # [ 0.272388] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint264machine # [ 0.272877] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint265machine # [ 0.273071] pci 0000:00:01.0: BAR 0 [io 0x0000-0x001f]266machine # [ 0.273086] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff]267machine # [ 0.273115] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]268machine # [ 0.273130] pci 0000:00:01.0: ROM [mem 0x00000000-0x0003ffff pref]269machine # [ 0.273634] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint270machine # [ 0.273827] pci 0000:00:02.0: BAR 0 [io 0x0000-0x001f]271machine # [ 0.273840] pci 0000:00:02.0: BAR 1 [mem 0x00000000-0x00000fff]272machine # [ 0.273870] pci 0000:00:02.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]273machine # [ 0.274364] pci 0000:00:03.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint274machine # [ 0.274556] pci 0000:00:03.0: BAR 0 [io 0x0000-0x007f]275machine # [ 0.274572] pci 0000:00:03.0: BAR 1 [mem 0x00000000-0x00000fff]276machine # [ 0.274601] pci 0000:00:03.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]277machine # [ 0.275091] pci 0000:00:04.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint278machine # [ 0.275285] pci 0000:00:04.0: BAR 0 [io 0x0000-0x001f]279machine # [ 0.275299] pci 0000:00:04.0: BAR 1 [mem 0x00000000-0x00000fff]280machine # [ 0.275328] pci 0000:00:04.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]281machine # [ 0.275342] pci 0000:00:04.0: ROM [mem 0x00000000-0x0003ffff pref]282machine # [ 0.284349] pci 0000:00:05.0: [1af4:1050] type 00 class 0x038000 conventional PCI endpoint283machine # [ 0.284546] pci 0000:00:05.0: BAR 1 [mem 0x00000000-0x00000fff]284machine # [ 0.284575] pci 0000:00:05.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]285machine # [ 0.285061] pci 0000:00:06.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint286machine # [ 0.285256] pci 0000:00:06.0: BAR 1 [mem 0x00000000-0x00000fff]287machine # [ 0.285286] pci 0000:00:06.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]288machine # [ 0.285700] pci 0000:00:07.0: [8086:24cd] type 00 class 0x0c0320 conventional PCI endpoint289machine # [ 0.285891] pci 0000:00:07.0: BAR 0 [mem 0x00000000-0x00000fff]290machine # [ 0.286198] pci 0000:00:08.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint291machine # [ 0.286443] pci 0000:00:08.0: BAR 1 [mem 0x00000000-0x00000fff]292machine # [ 0.286473] pci 0000:00:08.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]293machine # [ 0.286954] pci 0000:00:09.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint294machine # [ 0.287149] pci 0000:00:09.0: BAR 1 [mem 0x00000000-0x00000fff]295machine # [ 0.287178] pci 0000:00:09.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]296machine # [ 0.287690] pci 0000:00:0a.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint297machine # [ 0.287884] pci 0000:00:0a.0: BAR 1 [mem 0x00000000-0x00000fff]298machine # [ 0.287914] pci 0000:00:0a.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]299machine # [ 0.288411] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint300machine # [ 0.288689] pci 0000:00:0b.0: BAR 0 [io 0x0000-0x003f]301machine # [ 0.288705] pci 0000:00:0b.0: BAR 1 [mem 0x00000000-0x00000fff]302machine # [ 0.288734] pci 0000:00:0b.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]303machine # [ 0.289240] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint304machine # [ 0.289433] pci 0000:00:0c.0: BAR 0 [io 0x0000-0x001f]305machine # [ 0.289449] pci 0000:00:0c.0: BAR 1 [mem 0x00000000-0x00000fff]306machine # [ 0.289480] pci 0000:00:0c.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]307machine # [ 0.290120] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned308machine # [ 0.290129] pci 0000:00:04.0: ROM [mem 0x10040000-0x1007ffff pref]: assigned309machine # [ 0.290132] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned310machine # [ 0.290177] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned311machine # [ 0.290223] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned312machine # [ 0.290269] pci 0000:00:04.0: BAR 4 [mem 0x800000c000-0x800000ffff 64bit pref]: assigned313machine # [ 0.290315] pci 0000:00:05.0: BAR 4 [mem 0x8000010000-0x8000013fff 64bit pref]: assigned314machine # [ 0.290372] pci 0000:00:06.0: BAR 4 [mem 0x8000014000-0x8000017fff 64bit pref]: assigned315machine # [ 0.290419] pci 0000:00:08.0: BAR 4 [mem 0x8000018000-0x800001bfff 64bit pref]: assigned316machine # [ 0.290466] pci 0000:00:09.0: BAR 4 [mem 0x800001c000-0x800001ffff 64bit pref]: assigned317machine # [ 0.290511] pci 0000:00:0a.0: BAR 4 [mem 0x8000020000-0x8000023fff 64bit pref]: assigned318machine # [ 0.290558] pci 0000:00:0b.0: BAR 4 [mem 0x8000024000-0x8000027fff 64bit pref]: assigned319machine # [ 0.290628] pci 0000:00:0c.0: BAR 4 [mem 0x8000028000-0x800002bfff 64bit pref]: assigned320machine # [ 0.290675] pci 0000:00:01.0: BAR 1 [mem 0x10080000-0x10080fff]: assigned321machine # [ 0.290695] pci 0000:00:02.0: BAR 1 [mem 0x10081000-0x10081fff]: assigned322machine # [ 0.290714] pci 0000:00:03.0: BAR 1 [mem 0x10082000-0x10082fff]: assigned323machine # [ 0.290737] pci 0000:00:04.0: BAR 1 [mem 0x10083000-0x10083fff]: assigned324machine # [ 0.290758] pci 0000:00:05.0: BAR 1 [mem 0x10084000-0x10084fff]: assigned325machine # [ 0.290777] pci 0000:00:06.0: BAR 1 [mem 0x10085000-0x10085fff]: assigned326machine # [ 0.290798] pci 0000:00:07.0: BAR 0 [mem 0x10086000-0x10086fff]: assigned327machine # [ 0.290818] pci 0000:00:08.0: BAR 1 [mem 0x10087000-0x10087fff]: assigned328machine # [ 0.290838] pci 0000:00:09.0: BAR 1 [mem 0x10088000-0x10088fff]: assigned329machine # [ 0.290859] pci 0000:00:0a.0: BAR 1 [mem 0x10089000-0x10089fff]: assigned330machine # [ 0.290881] pci 0000:00:0b.0: BAR 1 [mem 0x1008a000-0x1008afff]: assigned331machine # [ 0.290902] pci 0000:00:0c.0: BAR 1 [mem 0x1008b000-0x1008bfff]: assigned332machine # [ 0.290922] pci 0000:00:03.0: BAR 0 [io 0x1000-0x107f]: assigned333machine # [ 0.290941] pci 0000:00:0b.0: BAR 0 [io 0x1080-0x10bf]: assigned334machine # [ 0.290961] pci 0000:00:01.0: BAR 0 [io 0x10c0-0x10df]: assigned335machine # [ 0.290983] pci 0000:00:02.0: BAR 0 [io 0x10e0-0x10ff]: assigned336machine # [ 0.291002] pci 0000:00:04.0: BAR 0 [io 0x1100-0x111f]: assigned337machine # [ 0.291021] pci 0000:00:0c.0: BAR 0 [io 0x1120-0x113f]: assigned338machine # [ 0.291044] pci_bus 0000:00: resource 4 [io 0x0000-0xffff]339machine # [ 0.291050] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]340machine # [ 0.291053] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]341machine # [ 0.316185] pci 0000:00:07.0: enabling device (0000 -> 0002)342machine # [ 0.351865] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)343machine # [ 0.354207] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)344machine # [ 0.364281] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)345machine # [ 0.366729] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)346machine # [ 0.369103] virtio-pci 0000:00:05.0: enabling device (0000 -> 0002)347machine # [ 0.371239] virtio-pci 0000:00:06.0: enabling device (0000 -> 0002)348machine # [ 0.381159] virtio-pci 0000:00:08.0: enabling device (0000 -> 0002)349machine # [ 0.383294] virtio-pci 0000:00:09.0: enabling device (0000 -> 0002)350machine # [ 0.385465] virtio-pci 0000:00:0a.0: enabling device (0000 -> 0002)351machine # [ 0.389412] virtio-pci 0000:00:0b.0: enabling device (0000 -> 0003)352machine # [ 0.394353] virtio-pci 0000:00:0c.0: enabling device (0000 -> 0003)353machine # [ 0.405022] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled354machine # [ 0.407024] msm_serial: driver initialized355machine # [ 0.407160] SuperH (H)SCI(F) driver initialized356machine # [ 0.407230] STM32 USART driver initialized357machine # [ 0.430699] loop: module loaded358machine # [ 0.430929] virtio_blk virtio2: 2/0/0 default/read/poll queues359machine # [ 0.432103] virtio_blk virtio2: [vda] 16777216 512-byte logical blocks (8.59 GB/8.00 GiB)360machine # [ 0.434069] megasas: 07.734.00.00-rc1361machine # [ 0.434859] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]362machine # [ 0.439920] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000363machine # [ 0.439943] Intel/Sharp Extended Query Table at 0x0031364machine # [ 0.441559] Using buffer write method365machine # [ 0.441625] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]366machine # [ 0.443492] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000367machine # [ 0.443515] Intel/Sharp Extended Query Table at 0x0031368machine # [ 0.444972] Using buffer write method369machine # [ 0.445127] Concatenating MTD devices:370machine # [ 0.445131] (0): "0.flash"371machine # [ 0.445133] (1): "0.flash"372machine # [ 0.445135] into device "0.flash"373machine # [ 0.660587] Freeing initrd memory: 26944K374machine # [ 0.669268] tun: Universal TUN/TAP device driver, 1.6375machine # [ 0.672977] thunder_xcv, ver 1.0376machine # [ 0.673013] thunder_bgx, ver 1.0377machine # [ 0.673032] nicpf, ver 1.0378machine # [ 0.673657] e1000: Intel(R) PRO/1000 Network Driver379machine # [ 0.673662] e1000: Copyright (c) 1999-2006 Intel Corporation.380machine # [ 0.673684] e1000e: Intel(R) PRO/1000 Network Driver381machine # [ 0.673690] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.382machine # [ 0.673719] igb: Intel(R) Gigabit Ethernet Network Driver383machine # [ 0.673722] igb: Copyright (c) 2007-2014 Intel Corporation.384machine # [ 0.673743] igbvf: Intel(R) Gigabit Virtual Function Network Driver385machine # [ 0.673746] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.386machine # [ 0.673904] sky2: driver version 1.30387machine # [ 0.675731] usbcore: registered new interface driver usb-storage388machine # [ 0.675873] usbcore: registered new interface driver usbserial_generic389machine # [ 0.675887] usbserial: USB Serial support registered for generic390machine # [ 0.676224] ehci-pci 0000:00:07.0: EHCI Host Controller391machine # [ 0.676262] ehci-pci 0000:00:07.0: new USB bus registered, assigned bus number 1392machine # [ 0.676552] hv_vmbus: registering driver hyperv_keyboard393machine # [ 0.676660] ehci-pci 0000:00:07.0: irq 16, io mem 0x10086000394machine # [ 0.677536] rtc-pl031 9010000.pl031: registered as rtc0395machine # [ 0.677566] rtc-pl031 9010000.pl031: setting system clock to 2026-10-06T09:19:32 UTC (1791278372)396machine # [ 0.677913] i2c_dev: i2c /dev entries driver397machine # [ 0.681383] sdhci: Secure Digital Host Controller Interface driver398machine # [ 0.681393] sdhci: Copyright(c) Pierre Ossman399machine # [ 0.681691] Synopsys Designware Multimedia Card Interface Driver400machine # [ 0.682097] sdhci-pltfm: SDHCI platform and OF driver helper401machine # [ 0.683778] hid: raw HID events driver (C) Jiri Kosina402machine # [ 0.684057] usbcore: registered new interface driver usbhid403machine # [ 0.684061] usbhid: USB HID core driver404machine # [ 0.708348] ehci-pci 0000:00:07.0: USB 2.0 started, EHCI 1.00405machine # [ 0.709028] hub 1-0:1.0: USB hub found406machine # [ 0.709053] hub 1-0:1.0: 6 ports detected407machine # [ 0.714784] hw perfevents: enabled with armv8_pmuv3 PMU driver, 11 (0,800003ff) counters available408machine # [ 0.716547] drop_monitor: Initializing network drop monitor service409machine # [ 0.716747] NET: Registered PF_INET6 protocol family410machine # [ 0.717368] Segment Routing with IPv6411machine # [ 0.717381] In-situ OAM (IOAM) with IPv6412machine # [ 0.717424] NET: Registered PF_PACKET protocol family413machine # [ 0.717511] 9pnet: Installing 9P2000 support414machine # [ 0.717561] Key type dns_resolver registered415machine # [ 0.723824] registered taskstats version 1416machine # [ 0.724012] Loading compiled-in X.509 certificates417machine # [ 0.731637] Demotion targets for Node 0: null418machine # [ 0.731789] Key type .fscrypt registered419machine # [ 0.731794] Key type fscrypt-provisioning registered420machine # [ 0.731894] ima: No TPM chip found, activating TPM-bypass!421machine # [ 0.731912] ima: Allocated hash algorithm: sha1422machine # [ 0.731936] ima: No architecture policies found423machine # [ 0.732791] input: gpio-keys as /devices/platform/gpio-keys/input/input0424machine # [ 0.769079] clk: Disabling unused clocks425machine # [ 0.769100] PM: genpd: Disabling unused power domains426machine # [ 0.772144] Freeing unused kernel memory: 4736K427machine # [ 0.772357] Run /init as init process428machine # [ 0.790048] systemd[1]: Successfully made /usr/ read-only.429machine # [ 0.951607] usb 1-1: new high-speed USB device number 2 using ehci-pci430machine # [ 1.099476] input: QEMU QEMU USB Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:07.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input1431machine # [ 1.124126] systemd[1]: systemd 261.3 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -BTF -XKBCOMMON +UTMP +LIBARCHIVE)432machine # [ 1.124154] systemd[1]: Detected virtualization qemu.433machine # [ 1.124195] systemd[1]: Detected architecture arm64.434machine # [ 1.124204] systemd[1]: Running in initrd.435machine # [ 1.124708] systemd[1]: Initializing machine ID from random generator.436machine # [ 1.124963] systemd[1]: Hostname set to <machine>.437machine # [ 1.211584] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:07.0-1/input0438machine # [ 1.264172] systemd[1]: bpf-restrict-fs: LSM BPF program attached439machine # [ 1.335581] usb 1-2: new high-speed USB device number 3 using ehci-pci440machine # [ 1.338297] systemd[1]: Queued start job for default target Initrd Default Target.441machine # [ 1.351105] systemd[1]: Created slice Slice /system/modprobe.442machine # [ 1.351399] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.443machine # [ 1.351441] systemd[1]: Expecting device /dev/disk/by-label/nixos...444machine # [ 1.351469] systemd[1]: Reached target Path Units.445machine # [ 1.351489] systemd[1]: Reached target Slice Units.446machine # [ 1.351508] systemd[1]: Reached target Swaps.447machine # [ 1.351587] systemd[1]: Reached target Timer Units.448machine # [ 1.351816] systemd[1]: Listening on D-Bus System Message Bus Socket.449machine # [ 1.352001] systemd[1]: Listening on Journal Socket (/dev/log).450machine # [ 1.352220] systemd[1]: Listening on Journal Sockets.451machine # [ 1.352386] systemd[1]: Listening on udev Control Socket.452machine # [ 1.352483] systemd[1]: Listening on udev Kernel Socket.453machine # [ 1.352504] systemd[1]: Reached target Socket Units.454machine # [ 1.354575] systemd[1]: Starting Create List of Static Device Nodes...455machine # [ 1.354681] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs456machine # [ 1.367775] systemd[1]: Mounting Kernel Configuration File System...457machine # [ 1.383915] systemd[1]: Starting Journal Service...458machine # [ 1.386735] systemd[1]: Starting Load Kernel Modules...459machine # [ 1.386897] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os460machine # [ 1.393226] systemd[1]: Starting Coldplug All udev Devices...461machine # [ 1.395366] systemd[1]: Finished Create List of Static Device Nodes.462machine # [ 1.397374] systemd[1]: Mounted Kernel Configuration File System.463machine # [ 1.399482] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...464machine # [ 1.429618] [drm] pci: virtio-gpu-pci detected at 0000:00:05.0465machine # [ 1.429853] [drm] features: -virgl +edid -resource_blob -host_visible466machine # [ 1.429856] [drm] features: -context_init467machine # [ 1.430699] [drm] number of scanouts: 1468machine # [ 1.430711] [drm] number of cap sets: 0469machine # [ 1.439634] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.470machine # [ 1.440474] systemd-journald[79]: Collecting audit messages is disabled.471machine # [ 1.444933] virtio-pci 0000:00:05.0: [drm] Registered 1 planes with drm panic472machine # [ 1.444949] [drm] Initialized virtio_gpu 0.1.0 for 0000:00:05.0 on minor 0473machine # [ 1.445253] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev474machine # [ 1.451746] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.475machine # [ 1.467697] systemd[1]: Starting Create Static Device Nodes in /dev...476machine # [ 1.483929] Console: switching to colour frame buffer device 160x50477machine # [ 1.484614] virtio-pci 0000:00:05.0: [drm] fb0: virtio_gpudrmfb frame buffer device478machine # [ 1.496937] input: QEMU QEMU USB Tablet as /devices/platform/4010000000.pcie/pci0000:00/0000:00:07.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input2479machine # [ 1.497691] systemd[1]: Finished Create Static Device Nodes in /dev.480machine # [ 1.497913] systemd[1]: Reached target Preparation for Local File Systems.481machine # [ 1.497946] systemd[1]: Reached target Local File Systems.482machine # [ 1.499490] hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:07.0-2/input0483machine # [ 1.500035] systemd[1]: Starting Rule-based Manager for Device Events and Files...484machine # [ 1.511827] systemd[1]: Finished Load Kernel Modules.485machine # [ 1.529408] systemd-modules-load[80]: Using 2 probe threads486machine # [ 1.530652] systemd-modules-load[80]: Module 'virtio_balloon' is built in487machine # [ 1.531887] systemd-modules-load[80]: Module 'virtio_console' is built in488machine # [ 1.537744] systemd-modules-load[80]: Inserted module 'dm_mod'489machine # [ 1.538779] systemd-modules-load[80]: Module 'virtio_rng' is built in490machine # [ 1.539834] systemd-modules-load[80]: Inserted module 'virtio_gpu'491machine # [ 1.539742] systemd[1]: Starting Apply Kernel Variables...492machine # [ 1.540002] systemd[1]: Started Journal Service.493machine # [ 1.556398] systemd[1]: Starting Create System Files and Directories...494machine # [ 1.573879] systemd[1]: Finished Apply Kernel Variables.495machine # [ 1.583514] systemd-udevd[88]: Using default interface naming scheme 'v261'.496machine # [ 1.585630] systemd[1]: Finished Create System Files and Directories.497machine # [ 1.601029] systemd[1]: Started Rule-based Manager for Device Events and Files.498machine # [ 1.634011] systemd[1]: Starting Virtual Console Setup...499machine # [ 1.666407] systemd-vconsole-setup[111]: Configuration of first virtual console was skipped, ignoring remaining ones.500machine # [ 1.669983] systemd[1]: Finished Virtual Console Setup.501machine # [ 2.088527] systemd[1]: Finished Coldplug All udev Devices.502machine # [ 2.090282] systemd[1]: Reached target System Initialization.503machine # [ 2.091237] systemd[1]: Reached target Basic System.504machine # [ 2.223851] (udev-worker)[110]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.505machine # [ 2.227743] (udev-worker)[110]: Network interface NamePolicy= disabled on kernel command line.506machine # [ 2.241520] (udev-worker)[123]: Network interface NamePolicy= disabled on kernel command line.507machine # [ 2.312363] systemd[1]: Found device /dev/disk/by-label/nixos.508machine # [ 2.314892] systemd[1]: Reached target Initrd Root Device.509machine # [ 2.323569] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos...510machine # [ 2.363930] systemd-fsck[129]: nixos: clean, 12/524288 files, 58513/2097152 blocks511machine # [ 2.371286] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos.512machine # [ 2.392172] systemd[1]: Mounting /sysroot...513machine # [ 2.435125] EXT4-fs (vda): mounted filesystem a75c17f9-9e0f-4894-ad5a-aadd76e87b17 r/w with ordered data mode. Quota mode: none.514machine # [ 2.439090] systemd[1]: Mounted /sysroot.515machine # [ 2.440296] systemd[1]: Reached target Initrd Root File System.516machine # [ 2.443190] systemd[1]: Mounting /sysroot/nix/.ro-store...517machine # [ 2.448259] systemd[1]: Mounting /sysroot/nix/.rw-store...518machine # [ 2.461774] systemd[1]: Mounting /sysroot/run...519machine # [ 2.477193] systemd[1]: Mounting /sysroot/tmp/shared...520machine # [ 2.504152] systemd[1]: Mounting /sysroot/tmp/xchg...521machine # [ 2.515084] systemd-sysroot-fstab-check[144]: /sysroot should be mounted in the initrd, will request daemon-reload.[ 2.518772] fuse: init (API version 7.45)522machine # 523machine # [ 2.524611] systemd[1]: Starting Mountpoints Configured in the Real Root...524machine # [ 2.525744] systemd[1]: Mounted /sysroot/nix/.rw-store.525machine # [ 2.533953] virtiofs virtio6: discovered new tag: nix-store526machine # [ 2.534845] virtiofs virtio6: virtio_fs_setup_dax: No cache capability527machine # [ 2.541397] systemd[1]: Mounted /sysroot/run.528machine # [ 2.542631] systemd[1]: Reload requested from client PID 144 ('systemd-sysroot') (unit initrd-parse-etc.service)...529machine # [ 2.547925] systemd[1]: Reloading...530machine # [ 2.553864] virtiofs virtio7: discovered new tag: shared531machine # [ 2.554664] virtiofs virtio7: virtio_fs_setup_dax: No cache capability532machine # [ 2.572873] virtiofs virtio8: discovered new tag: xchg533machine # [ 2.630756] virtiofs virtio8: virtio_fs_setup_dax: No cache capability534machine # [ 2.810585] systemd[1]: Reloading finished in 270 ms.535machine # [ 2.855070] systemd-sysroot-fstab-check[144]: Requesting initrd-fs.target/start/replace...536machine # [ 2.860976] systemd[1]: Mounted /sysroot/nix/.ro-store.537machine # [ 2.861882] systemd[1]: Mounted /sysroot/tmp/shared.538machine # [ 2.862632] systemd[1]: Mounted /sysroot/tmp/xchg.539machine # [ 2.866551] systemd-sysroot-fstab-check[144]: Requesting swap.target/start/replace...540machine # [ 2.871769] systemd[1]: initrd-parse-etc.service: Deactivated successfully.541machine # [ 2.875198] systemd[1]: Finished Mountpoints Configured in the Real Root.542machine # [ 2.876873] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies.543machine # [ 2.878036] systemd[1]: Starting rw-sysroot-nix-store.service...544machine # [ 2.901656] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.545machine # [ 2.903392] systemd[1]: Finished rw-sysroot-nix-store.service.546machine # [ 3.188314] (udev-worker)[117]: mtd0ro: Failed to find and pin callout binary "/nix/store/8w0qabyr98chcmr4y9hh6h6l26albldx-systemd-261.3/lib/udev/mtd_probe": No such file or directory547machine # [ 3.192158] (udev-worker)[117]: mtd0ro: /etc/udev/rules.d/75-probe_mtd.rules:5 IMPORT{program}="mtd_probe $devnode": Failed to execute "mtd_probe /dev/mtd0ro", ignoring: No such file or directory548machine # [ 3.213211] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.549machine # [ 3.214483] systemd[1]: Stopped Virtual Console Setup.550machine # [ 3.215988] systemd[1]: Stopping Virtual Console Setup...551machine # [ 3.223133] systemd[1]: Starting Virtual Console Setup...552machine # [ 3.224127] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.553machine # [ 3.225223] systemd[1]: Stopped Virtual Console Setup.554machine # [ 3.226000] systemd[1]: Starting Virtual Console Setup...555machine # [ 3.261224] systemd-vconsole-setup[179]: Configuration of first virtual console was skipped, ignoring remaining ones.556machine # [ 3.263024] systemd[1]: Finished Virtual Console Setup.557machine # [ 3.394933] systemd[1]: Mounting /sysroot/nix/store...558machine # [ 3.447161] systemd[1]: Mounted /sysroot/nix/store.559machine # [ 3.448593] systemd[1]: Reached target Initrd File Systems.560machine # [ 3.452145] systemd[1]: Starting Find NixOS closure...561machine # [ 3.454670] systemd[1]: Starting Create Volatile Files and Directories in the Real Root...562machine # [ 3.489011] systemd[1]: Finished Create Volatile Files and Directories in the Real Root.563machine # [ 3.492708] systemd[1]: sysroot-run-credentials-systemd\x2dtmpfiles\x2dsetup\x2dsysroot.service.mount: Deactivated successfully.564machine # [ 3.505924] systemd[1]: Finished Find NixOS closure.565machine # [ 3.507404] systemd[1]: Reached target Initrd Default Target.566machine # [ 3.509064] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...567machine # [ 3.541198] systemd[1]: Stopped target Initrd Default Target.568machine # [ 3.542937] systemd[1]: Stopped target Basic System.569machine # [ 3.544684] systemd[1]: Stopped target Initrd Root Device.570machine # [ 3.545971] systemd[1]: Stopped target Path Units.571machine # [ 3.547184] systemd[1]: systemd-ask-password-console.path: Deactivated successfully.572machine # [ 3.548965] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.573machine # [ 3.550696] systemd[1]: Stopped target Slice Units.574machine # [ 3.551852] systemd[1]: Stopped target Socket Units.575machine # [ 3.553135] systemd[1]: Stopped target System Initialization.576machine # [ 3.554435] systemd[1]: Stopped target Swaps.577machine # [ 3.555527] systemd[1]: Stopped target Timer Units.578machine # [ 3.558701] systemd[1]: dbus.socket: Deactivated successfully.579machine # [ 3.561803] systemd[1]: Closed D-Bus System Message Bus Socket.580machine # [ 3.564601] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully.581machine # [ 3.568328] systemd[1]: Stopped Find NixOS closure.582machine # [ 3.570265] systemd[1]: Starting rw-sysroot-nix-store.service...583machine # [ 3.575502] systemd[1]: systemd-sysctl.service: Deactivated successfully.584machine # [ 3.577127] systemd[1]: Stopped Apply Kernel Variables.585machine # [ 3.578196] systemd[1]: systemd-modules-load.service: Deactivated successfully.586machine # [ 3.579584] systemd[1]: Stopped Load Kernel Modules.587machine # [ 3.582478] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully.588machine # [ 3.584882] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root.589machine # [ 3.586466] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.590machine # [ 3.587812] systemd[1]: Stopped Create System Files and Directories.591machine # [ 3.589251] systemd[1]: Stopped target Local File Systems.592machine # [ 3.590201] systemd[1]: Stopped target Preparation for Local File Systems.593machine # [ 3.591782] systemd[1]: systemd-udev-trigger.service: Deactivated successfully.594machine # [ 3.593043] systemd[1]: Stopped Coldplug All udev Devices.595machine # [ 3.593953] systemd[1]: Stopping Rule-based Manager for Device Events and Files...596machine # [ 3.595210] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.597machine # [ 3.596542] systemd[1]: Stopped Virtual Console Setup.598machine # [ 3.597392] systemd[1]: initrd-cleanup.service: Deactivated successfully.599machine # [ 3.598450] systemd[1]: Finished Cleaning Up and Shutting Down Daemons.600machine # [ 3.601111] systemd[1]: systemd-udevd.service: Deactivated successfully.601machine # [ 3.602775] systemd[1]: Stopped Rule-based Manager for Device Events and Files.602machine # [ 3.604861] systemd[1]: systemd-udevd.service: Consumed 1.839s CPU time over 2.093s wall clock time, 29.9M memory peak.603machine # [ 3.607162] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.604machine # [ 3.609081] systemd[1]: Finished rw-sysroot-nix-store.service.605machine # [ 3.610357] systemd[1]: systemd-udevd-control.socket: Deactivated successfully.606machine # [ 3.612208] systemd[1]: Closed udev Control Socket.607machine # [ 3.613493] systemd[1]: Starting Cleanup udev Database...608machine # [ 3.614673] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.609machine # [ 3.616308] systemd[1]: Stopped Create Static Device Nodes in /dev.610machine # [ 3.617606] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully.611machine # [ 3.619316] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully.612machine # [ 3.620916] systemd[1]: kmod-static-nodes.service: Deactivated successfully.613machine # [ 3.622343] systemd[1]: Stopped Create List of Static Device Nodes.614machine # [ 3.652910] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.615machine # [ 3.654701] systemd[1]: Finished Cleanup udev Database.616machine # [ 3.655934] systemd[1]: Reached target Switch Root.617machine # [ 3.657260] systemd[1]: Starting NixOS Activation...618machine # [ 3.770692] initrd-nixos-activation-start[202]: booting system configuration /nix/store/sb3qmfpvc24zwlmnr17fywvj0v0p7fbh-nixos-system-machine-test619machine # [ 3.805761] initrd-nixos-activation-start[202]: running activation script...620machine # [ 4.074650] initrd-nixos-activation-start[225]: setting up /etc...621machine # [ 4.213209] systemd[1]: initrd-nixos-activation.service: Deactivated successfully.622machine # [ 4.214996] systemd[1]: Finished NixOS Activation.623machine # [ 4.216207] systemd[1]: Starting Switch Root...624machine # [ 4.245716] systemd[1]: Switching root.625machine # [ 4.365515] systemd-journald[79]: Received SIGTERM from PID 1 (systemd).626machine # [ 5.101475] systemd[1]: systemd 261.3 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -BTF -XKBCOMMON +UTMP +LIBARCHIVE)627machine # [ 5.101537] systemd[1]: Detected virtualization qemu.628machine # [ 5.101603] systemd[1]: Detected architecture arm64.629machine # [ 5.101724] systemd[1]: Detected first boot.630machine # [ 5.104707] systemd[1]: Initializing machine ID from random generator.631machine # [ 5.242871] systemd[1]: bpf-restrict-fs: LSM BPF program attached632machine # [ 5.356662] systemd[1]: Applying preset policy.633machine # [ 5.573378] systemd[1]: Populated /etc with preset unit settings.634machine # [ 5.807774] systemd[1]: initrd-switch-root.service: Deactivated successfully.635machine # [ 5.808525] systemd[1]: Stopped initrd-switch-root.service.636machine # [ 5.810470] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.637machine # [ 5.814186] systemd[1]: Created slice Slice /system/getty.638machine # [ 5.816633] systemd[1]: Created slice User and Session Slice.639machine # [ 5.817285] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.640machine # [ 5.817887] systemd[1]: Started Forward Password Requests to Wall Directory Watch.641machine # [ 5.818467] systemd[1]: Expecting device /dev/hvc0...642machine # [ 5.819045] systemd[1]: Expecting device /dev/ttyAMA0...643machine # [ 5.819723] systemd[1]: Reached target Local Encrypted Volumes.644machine # [ 5.820273] systemd[1]: Stopped target initrd-fs.target.645machine # [ 5.820851] systemd[1]: Stopped target initrd-root-fs.target.646machine # [ 5.821436] systemd[1]: Stopped target initrd-switch-root.target.647machine # [ 5.822034] systemd[1]: Reached target Virtual Machines and Containers.648machine # [ 5.822626] systemd[1]: Reached target Path Units.649machine # [ 5.823194] systemd[1]: Reached target Remote File Systems.650machine # [ 5.823863] systemd[1]: Reached target Slice Units.651machine # [ 5.824427] systemd[1]: Reached target Swaps.652machine # [ 5.826613] systemd[1]: Listening on Query the User Interactively for a Password.653machine # [ 5.830466] systemd[1]: Listening on Process Core Dump Socket.654machine # [ 5.832179] systemd[1]: Listening on Credential Encryption/Decryption.655machine # [ 5.833991] systemd[1]: Listening on Factory Reset Management.656machine # [ 5.834596] systemd[1]: Listening on Hostname Service Socket.657machine # [ 5.839017] systemd[1]: Starting Journal Log Access Socket...658machine # [ 5.841157] systemd[1]: Listening on Journal Audit Socket.659machine # [ 5.843241] systemd[1]: Listening on Console Output Muting Service Socket.660machine # [ 5.843958] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.661machine # [ 5.844435] systemd[1]: TPM PCR Measurements skipped, unmet condition check ConditionSecurity=measured-os662machine # [ 5.844852] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki663machine # [ 5.848260] systemd[1]: Listening on Disk Repartitioning Service Socket.664machine # [ 5.848784] systemd[1]: Listening on udev Control Socket.665machine # [ 5.849318] systemd[1]: Listening on udev Varlink Socket.666machine # [ 5.863895] systemd[1]: Mounting Huge Pages File System...667machine # [ 5.866907] systemd[1]: Mounting POSIX Message Queue File System...668machine # [ 5.872152] systemd[1]: Mounting Kernel Debug File System...669machine # [ 5.878171] systemd[1]: Mounting Kernel Trace File System...670machine # [ 5.892716] systemd[1]: Starting Create List of Static Device Nodes...671machine # [ 5.893311] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs672machine # [ 5.898967] systemd[1]: Mounting Kernel Configuration File System...673machine # [ 5.899819] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm674machine # [ 5.900303] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore675machine # [ 5.900823] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse676machine # [ 5.906830] systemd[1]: Mounting FUSE Control File System...677machine # [ 5.907861] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67678machine # [ 5.915379] systemd[1]: Starting Journal Service...679machine # [ 5.923187] systemd[1]: Starting Load Kernel Modules...680machine # [ 5.935450] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...681machine # [ 5.948033] systemd[1]: Starting Remount Root and Kernel File Systems...682machine # [ 5.949754] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os683machine # [ 5.970920] systemd[1]: Starting Coldplug All udev Devices...684machine # [ 5.981042] systemd[1]: Listening on Journal Log Access Socket.685machine # [ 5.994716] systemd[1]: Mounted Huge Pages File System.686machine # [ 5.996127] systemd[1]: Mounted POSIX Message Queue File System.687machine # [ 5.996972] systemd[1]: Mounted Kernel Debug File System.688machine # [ 5.997651] systemd[1]: Mounted Kernel Configuration File System.689machine # [ 5.998316] systemd[1]: Mounted FUSE Control File System.690machine # [ 6.004818] systemd[1]: Mounted Kernel Trace File System.691machine # [ 6.017511] systemd[1]: Finished Create List of Static Device Nodes.692machine # [ 6.024035] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...693machine # [ 6.040859] systemd-journald[295]: Collecting audit messages is enabled.694machine # [ 6.052023] EXT4-fs (vda): re-mounted a75c17f9-9e0f-4894-ad5a-aadd76e87b17.695machine # [ 6.062813] systemd[1]: Queued start job for default target Multi-User System.696machine # [ 6.064918] systemd[1]: Finished Remount Root and Kernel File Systems.697machine # [ 6.065552] systemd[1]: Listening on Disk Image Download Service Socket.698machine # [ 6.065864] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore699machine # [ 6.069780] systemd[1]: systemd-journald.service: Deactivated successfully.700machine # [ 6.073165] systemd[1]: Starting Load/Save OS Random Seed...701machine # [ 6.073622] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os702machine # [ 6.075879] systemd[1]: Started Journal Service.703machine # [ 6.077889] systemd-modules-load[296]: Using 2 probe threads704machine # [ 6.079251] systemd-modules-load[296]: Module 'atkbd' is built in705machine # [ 6.081055] systemd-modules-load[296]: Module 'loop' is built in706machine # [ 6.088664] systemd[1]: Starting Flush Journal to Persistent Storage...707machine # [ 6.121574] systemd[1]: Finished Load Kernel Modules.708machine # [ 6.124133] systemd[1]: Starting Apply Kernel Variables...709machine # [ 6.133312] systemd-oomd[297]: No swap; memory pressure usage will be degraded710machine # [ 6.141635] systemd-journald[295]: Received client request to flush runtime journal.711machine # [ 6.165850] systemd[1]: Finished Load/Save OS Random Seed.712machine # [ 6.166862] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.713machine # [ 6.167948] systemd[1]: Reached target First Boot Complete.714machine # [ 6.170603] systemd[1]: Finished Flush Journal to Persistent Storage.715machine # [ 6.186478] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.716machine # [ 6.190410] systemd[1]: Starting Create Static Device Nodes in /dev...717machine # [ 6.218289] systemd[1]: Finished Apply Kernel Variables.718machine # [ 6.244990] systemd[1]: Finished Create Static Device Nodes in /dev.719machine # [ 6.248168] systemd[1]: Reached target Preparation for Local File Systems.720machine # [ 6.252906] systemd[1]: Starting Rule-based Manager for Device Events and Files...721machine # [ 6.315228] systemd-udevd[328]: Using default interface naming scheme 'v261'.722machine # [ 6.353694] systemd[1]: Started Rule-based Manager for Device Events and Files.723machine # [ 6.742033] systemd[1]: Finished Coldplug All udev Devices.724machine # [ 6.809964] systemd[1]: Mounting /run/wrappers...725machine # [ 6.813163] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs726machine # [ 6.827092] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse727machine # [ 6.855379] systemd[1]: Mounted /run/wrappers.728machine # [ 6.858484] systemd[1]: Reached target Local File Systems.729machine # [ 6.864054] systemd[1]: Listening on Boot Loader Control Service Socket.730machine # [ 6.869644] systemd[1]: Starting register-nix-paths.service...731machine # [ 6.873429] systemd[1]: Starting Create SUID/SGID Wrappers...732machine # [ 6.880320] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.733machine # [ 6.884613] systemd[1]: Starting Save Transient machine-id to Disk...734machine # [ 6.892451] systemd[1]: Starting Create System Files and Directories...735machine # [ 6.938580] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.736machine # [ 6.941437] systemd[1]: Finished Save Transient machine-id to Disk.737machine # [ 6.994416] systemd[1]: Condition check resulted in /dev/hvc0 being skipped.738machine # [ 7.011416] systemd[1]: Finished Create System Files and Directories.739machine # [ 7.018893] systemd[1]: Starting Rebuild Journal Catalog...740machine # [ 7.023885] systemd[1]: Starting Record System Boot/Shutdown in UTMP...741machine # [ 7.084811] systemd[1]: Finished Record System Boot/Shutdown in UTMP.742machine # [ 7.118600] systemd[1]: Condition check resulted in /dev/ttyAMA0 being skipped.743machine # [ 7.128843] systemd[1]: Finished Rebuild Journal Catalog.744machine # [ 7.131240] systemd[1]: Starting Update is Completed...745machine # [ 7.196875] systemd[1]: Finished Update is Completed.746machine # [ 7.210905] (udev-worker)[341]: Network interface NamePolicy= disabled on kernel command line.747machine # [ 7.245036] (udev-worker)[340]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.748machine # [ 7.252397] (udev-worker)[340]: Network interface NamePolicy= disabled on kernel command line.749machine # [ 7.414972] systemd[1]: Condition check resulted in Virtio network device being skipped.750machine # [ 7.418255] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore751machine # [ 7.424248] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.752machine # [ 7.426149] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67753machine # [ 7.430489] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore754machine # [ 7.440045] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os755machine # [ 7.441626] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os756machine # [ 7.443029] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.757machine # [ 7.444528] systemd[1]: Finished Create SUID/SGID Wrappers.758machine # [ 7.500757] mousedev: PS/2 mouse device common for all mice759machine # [ 7.518636] systemd[1]: Finished register-nix-paths.service.760machine # [ 7.520264] systemd[1]: Reached target System Initialization.761machine # [ 7.524464] systemd[1]: Started Discard unused filesystem blocks once a week.762machine # [ 7.525664] systemd[1]: Started Daily Cleanup of Temporary Directories.763machine # [ 7.527713] systemd[1]: Reached target Timer Units.764machine # [ 7.531802] systemd[1]: Listening on D-Bus System Message Bus Socket.765machine # [ 7.540325] systemd[1]: Listening on Nix Daemon Socket.766machine # [ 7.543285] systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.767machine # [ 7.548992] systemd[1]: Reached target Socket Units.768machine # [ 7.549858] systemd[1]: Reached target Basic System.769machine # [ 7.551410] systemd[1]: Started backdoor.service.770machine # [ 7.552419] systemd[1]: Starting Import lastlog data into lastlog2 database...771machine # [ 7.564552] systemd[1]: Starting Name Service Cache Daemon (nsncd)...772machine # [ 7.567374] systemd[1]: Starting Post-Boot Actions...773machine # [ 7.582672] systemd[1]: Started Reset console on configuration changes.774machine # [ 7.588548] systemd[1]: Starting resolvconf update...775machine # [ 7.603344] systemd[1]: Starting D-Bus System Message Bus...776machine # connecting to host...777machine # [ 7.653787] systemd[1]: Finished Import lastlog data into lastlog2 database.778machine # [ 7.672654] systemd[1]: Finished Post-Boot Actions.779machine: Guest shell says: b'Spawning backdoor root shell...\n'780machine # [ 7.684126] systemd[1]: Started Name Service Cache Daemon (nsncd).781machine: connected to guest root shell782machine # [ 7.685161] systemd[1]: Reached target Host and Network Name Lookups.783machine: (connecting took 8.22 seconds)784machine # [ 7.691160] systemd[1]: Reached target User and Group Name Lookups.785machine: (finished: waiting for the VM to finish booting, in 8.76 seconds)786machine # [ 7.695694] nsncd[432]: Oct 06 09:19:39.512 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"787machine # [ 7.703960] systemd[1]: Starting User Login Management...788machine # [ 7.707434] dbus-broker-launch[437]: Looking up NSS user entry for 'systemd-timesync'...789machine # [ 7.732121] dbus-broker-launch[437]: NSS returned no entry for 'systemd-timesync'790machine # [ 7.734812] dbus-broker-launch[437]: Invalid user-name in /nix/store/4mpi5p6sfg7ag5ncsqmjc4ik386nsm7w-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"791machine # [ 7.773734] systemd[1]: Started D-Bus System Message Bus.792machine # [ 7.809347] dbus-broker-launch[437]: Ready793machine # [ 7.857854] systemd-logind[449]: Watching system buttons on /dev/input/event1 (QEMU QEMU USB Keyboard)794machine # [ 7.867676] systemd-logind[449]: Watching system buttons on /dev/input/event0 (gpio-keys)795machine # [ 7.873970] systemd-logind[449]: New seat seat0.796machine # [ 7.874858] systemd[1]: Started User Login Management.797machine # [ 7.875600] systemd[1]: Starting linger-users.service...798machine # [ 7.896183] systemd[1]: Stopped target Host and Network Name Lookups.799machine # [ 7.897258] systemd[1]: Stopping Host and Network Name Lookups...800machine # [ 7.903269] systemd[1]: Stopped target User and Group Name Lookups.801machine # [ 7.907079] systemd[1]: Stopping User and Group Name Lookups...802machine # [ 7.910098] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...803machine # [ 7.917151] systemd[1]: nscd.service: Deactivated successfully.804machine # [ 7.918137] systemd[1]: Stopped Name Service Cache Daemon (nsncd).805machine # [ 7.922207] systemd[1]: Starting Name Service Cache Daemon (nsncd)...806machine # [ 7.939184] systemd[1]: linger-users.service: Deactivated successfully.807machine # [ 7.944692] systemd[1]: Finished linger-users.service.808machine # [ 7.985852] systemd[1]: Started Name Service Cache Daemon (nsncd).809machine # [ 7.987062] systemd[1]: Reached target Host and Network Name Lookups.810machine # [ 7.989379] systemd[1]: Reached target User and Group Name Lookups.811machine # [ 7.995536] nsncd[513]: Oct 06 09:19:39.818 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"812machine # [ 8.015375] systemd[1]: Finished resolvconf update.813machine # [ 8.016326] systemd[1]: Reached target Preparation for Network.814machine # [ 8.021030] systemd[1]: Starting DHCP Client...815machine # [ 8.031819] systemd[1]: Starting Address configuration of eth1...816machine # [ 8.036938] systemd[1]: Starting Extra networking commands....817machine # [ 8.126718] network-addresses-eth1-start[541]: adding address 192.168.1.1/24... done818machine # [ 8.137639] network-addresses-eth1-start[541]: adding address 2001:db8:1::1/64... done819machine # [ 8.168469] systemd[1]: Finished Address configuration of eth1.820machine # [ 8.199777] dhcpcd[549]: dhcpcd-10.3.2 starting821machine # [ 8.207671] dhcpcd[578]: dev: loaded udev822machine # [ 8.232278] 8021q: 802.1Q VLAN Support v1.8823machine # [ 8.232663] 8021q: adding VLAN 0 to HW filter on device eth1824machine # [ 8.298878] cfg80211: Loading compiled-in X.509 certificates for regulatory database825machine # [ 8.316658] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'826machine # [ 8.317186] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'827machine # [ 8.318000] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2828machine # [ 8.318445] cfg80211: failed to load regulatory.db829machine # [ 8.337721] systemd[1]: Finished Extra networking commands..830machine # [ 8.338712] systemd[1]: Reached target Network.831machine # [ 8.342589] systemd[1]: Starting PostgreSQL Server...832machine # [ 8.346547] systemd[1]: Started RustFS S3-compatible object storage.833machine # [ 8.350797] systemd[1]: Starting Setup RustFS bucket...834machine # [ 8.361369] systemd[1]: Starting Permit User Sessions...835machine # [ 8.424619] systemd[1]: Finished Permit User Sessions.836machine # [ 8.427987] systemd[1]: Started Getty on tty1.837machine # [ 8.428894] systemd[1]: Reached target Login Prompts.838machine # [ 8.474703] 8021q: adding VLAN 0 to HW filter on device eth0839machine # [ 8.475063] dhcpcd[578]: eth0: waiting for carrier840machine # [ 8.478180] dhcpcd[578]: libudev: received NULL device841machine # [ 8.487934] dhcpcd[578]: libudev: received NULL device842machine # [ 8.489821] dhcpcd[578]: eth0: carrier acquired843machine # [ 8.511781] dhcpcd[578]: DUID 00:01:00:01:32:57:79:ac:52:54:00:12:34:56844machine # [ 8.515794] dhcpcd[578]: eth0: IAID 00:12:34:56845machine # [ 8.517827] dhcpcd[578]: eth0: adding address fe80::5054:ff:fe12:3456846machine # [ 8.668925] postgresql-pre-start[638]: The files belonging to this database system will be owned by user "postgres".847machine # [ 8.670617] postgresql-pre-start[638]: This user must also own the server process.848machine # [ 8.673320] postgresql-pre-start[638]: The database cluster will be initialized with locale "en_US.UTF-8".849machine # [ 8.677121] postgresql-pre-start[638]: The default database encoding has accordingly been set to "UTF8".850machine # [ 8.679375] postgresql-pre-start[638]: The default text search configuration will be set to "english".851machine # [ 8.681666] postgresql-pre-start[638]: Data page checksums are enabled.852machine # [ 8.683218] postgresql-pre-start[638]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok853machine # [ 8.686400] postgresql-pre-start[638]: creating subdirectories ... ok854machine # [ 8.687762] postgresql-pre-start[638]: selecting dynamic shared memory implementation ... posix855machine # [ 8.811948] postgresql-pre-start[638]: selecting default "max_connections" ... 100856machine # [ 8.911266] postgresql-pre-start[638]: selecting default "shared_buffers" ... 128MB857machine # [ 9.282419] input: QEMU Virtio Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:06.0/virtio5/input/input3858machine # [ 9.647286] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.859machine # [ 9.653756] systemd[1]: Starting Virtual Console Setup...860machine # [ 9.699642] systemd-logind[449]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)861machine # [ 9.756477] postgresql-pre-start[638]: selecting default time zone ... UTC862machine # [ 9.759834] postgresql-pre-start[638]: creating configuration files ... ok863machine # [ 9.789583] dhcpcd[578]: eth0: soliciting a DHCP lease864machine # [ 9.802030] systemd-vconsole-setup[696]: Configuration of first virtual console was skipped, ignoring remaining ones.865machine # [ 9.805214] dhcpcd[578]: eth0: offered 10.0.2.15 from 10.0.2.2866machine # [ 9.808353] systemd[1]: Finished Virtual Console Setup.867machine # [ 9.816483] dhcpcd[578]: eth0: probing address 10.0.2.15/24868machine # [ 10.016008] postgresql-pre-start[638]: running bootstrap script ... ok869machine # [ 10.100905] dhcpcd[578]: eth0: soliciting an IPv6 router870machine # [ 10.102261] dhcpcd[578]: eth0: Router Advertisement from fe80::2871machine # [ 10.103270] dhcpcd[578]: eth0: adding address fec0::5054:ff:fe12:3456/64872machine # [ 10.107123] dhcpcd[578]: eth0: adding route to fec0::/64873machine # [ 10.110346] dhcpcd[578]: eth0: adding default route via fe80::2874machine # [ 10.636545] postgresql-pre-start[638]: performing post-bootstrap initialization ... ok875machine # [ 10.753465] postgresql-pre-start[638]: syncing data to disk ... ok876machine # [ 10.755374] postgresql-pre-start[638]: initdb: warning: enabling "trust" authentication for local connections877machine # [ 10.758494] postgresql-pre-start[638]: initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.878machine # [ 10.762050] postgresql-pre-start[638]: Success. You can now start the database server using:879machine # [ 10.764071] postgresql-pre-start[638]: pg_ctl -D /var/lib/postgresql/18 -l logfile start880machine # [ 10.879376] postgres[715]: [715] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit881machine # [ 10.883187] postgres[715]: [715] LOG: listening on IPv4 address "0.0.0.0", port 5432882machine # [ 10.884764] postgres[715]: [715] LOG: listening on IPv6 address "::", port 5432883machine # [ 10.886055] postgres[715]: [715] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"884machine # [ 10.895774] postgres[724]: [724] LOG: database system was shut down at 2026-10-06 09:19:42 GMT885machine # [ 10.900789] postgres[715]: [715] LOG: database system is ready to accept connections886machine # [ 10.904697] systemd[1]: Started PostgreSQL Server.887machine # [ 10.909896] systemd[1]: Starting PostgreSQL Setup Scripts...888machine # [ 11.135520] postgresql-setup-start[735]: CREATE DATABASE889machine # [ 11.195418] postgresql-setup-start[744]: CREATE ROLE890machine # [ 11.220957] postgresql-setup-start[750]: ALTER DATABASE891machine # [ 11.225858] systemd[1]: Finished PostgreSQL Setup Scripts.892machine # [ 11.226864] systemd[1]: Reached target PostgreSQL.893machine # [ 14.741340] dhcpcd[578]: eth0: leased 10.0.2.15 for 86400 seconds894machine # [ 14.741549] dhcpcd[578]: eth0: adding route to 10.0.2.0/24895machine # [ 14.741628] dhcpcd[578]: eth0: adding default route via 10.0.2.2896machine # [ 14.886158] systemd[1]: Started DHCP Client.897machine # [ 14.889091] systemd[1]: Reached target Network is Online.898machine # [ 14.892909] systemd[1]: Starting k3s service...899machine # [ 14.959147] k3s[842]: time="2026-10-06T09:19:46Z" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock"900machine # [ 14.961902] k3s[842]: time="2026-10-06T09:19:46Z" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/de2d81a89f885789d196a36b4b2eb52dad0d670c45f31ccdb7b419eb73015dc5"901machine # [ 18.361729] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Starting k3s 1.36.4+k3s1 (4dedb15b)"902machine # [ 18.378444] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Configuring sqlite3 database connection pooling: maxIdle=20, maxOpen=0, maxLifetime=0s, maxIdleTime=2m0s"903machine # [ 18.381269] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Kine built with sqlite from github.com/mattn/go-sqlite3 version 3.53.3"904machine # [ 18.383335] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Configuring database table schema and indexes, this may take a moment..."905machine # [ 18.386950] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Database tables and indexes are up to date"906machine # [ 18.389459] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Running startup VACUUM to reclaim disk space, this may take a moment..."907machine # [ 18.392708] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Startup VACUUM completed successfully"908machine # [ 18.394309] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Kine available at unix://kine.sock"909machine # [ 18.395803] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"910machine # [ 18.397827] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Datastore connection validated successfully, proceeding with bootstrap data generation"911machine # [ 18.399914] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="generated self-signed CA certificate CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:50.22144464 +0000 UTC notAfter=2036-10-03 08:19:50.22144464 +0000 UTC"912machine # [ 18.403226] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"913machine # [ 18.406323] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=system:k3s-supervisor,O=system:masters signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"914machine # [ 18.409433] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"915machine # [ 18.412359] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"916machine # [ 18.415083] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=system:apiserver,O=system:masters signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"917machine # [ 18.418018] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"918machine # [ 18.420778] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="generated self-signed CA certificate CN=k3s-server-ca@1791278390: notBefore=2026-10-06 08:19:50.2280122 +0000 UTC notAfter=2036-10-03 08:19:50.2280122 +0000 UTC"919machine # [ 18.423413] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"920machine # [ 18.425976] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=kube-scheduler signed by CN=k3s-server-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"921machine # [ 18.428492] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=kube-controller-manager signed by CN=k3s-server-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"922machine # [ 18.431076] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="generated self-signed CA certificate CN=k3s-request-header-ca@1791278390: notBefore=2026-10-06 08:19:50.23145378 +0000 UTC notAfter=2036-10-03 08:19:50.23145378 +0000 UTC"923machine # [ 18.433901] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"924machine # [ 18.436494] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="generated self-signed CA certificate CN=etcd-server-ca@1791278390: notBefore=2026-10-06 08:19:50.23278194 +0000 UTC notAfter=2036-10-03 08:19:50.23278194 +0000 UTC"925machine # [ 18.439102] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"926machine # [ 18.442618] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="generated self-signed CA certificate CN=etcd-peer-ca@1791278390: notBefore=2026-10-06 08:19:50.23408058 +0000 UTC notAfter=2036-10-03 08:19:50.23408058 +0000 UTC"927machine # [ 18.445274] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"928machine # [ 18.447584] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"929machine # [ 18.603097] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1791278390: notBefore=2026-10-06 08:19:50 +0000 UTC notAfter=2027-10-06 08:19:50 +0000 UTC"930machine # [ 18.610783] k3s[842]: time="2026-10-06T09:19:50Z" level=warning msg="dynamiclistener [::]:6443: no cached certificate available for preload - deferring certificate load until storage initialization or first client request"931machine # [ 18.618038] k3s[842]: time="2026-10-06T09:19:50Z" level=info msg="Active TLS secret / (ver=) (count 11): map[listener.cattle.io/cn-10.0.2.15:10.0.2.15 listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-__1-f16284:::1 listener.cattle.io/cn-fec0__87bf_b810_8c62_a860-bd396f:fec0::87bf:b810:8c62:a860 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc:kubernetes.default.svc listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-localhost:localhost listener.cattle.io/cn-machine:machine listener.cattle.io/fingerprint:SHA1=183580988D4007062C343BA220CB0F2239A65041]"932machine # [ 19.949286] k3s[842]: time="2026-10-06T09:19:51Z" level=info msg="Password verified locally for node machine"933machine # [ 19.951046] k3s[842]: time="2026-10-06T09:19:51Z" level=info msg="certificate CN=machine signed by CN=k3s-server-ca@1791278390: notBefore=2026-10-06 08:19:51 +0000 UTC notAfter=2027-10-06 08:19:51 +0000 UTC"934machine # [ 20.334011] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="certificate CN=system:node:machine,O=system:nodes signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:52 +0000 UTC notAfter=2027-10-06 08:19:52 +0000 UTC"935machine # [ 20.474737] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:52 +0000 UTC notAfter=2027-10-06 08:19:52 +0000 UTC"936machine # [ 20.612836] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1791278390: notBefore=2026-10-06 08:19:52 +0000 UTC notAfter=2027-10-06 08:19:52 +0000 UTC"937machine # [ 20.759539] k3s[842]: time="2026-10-06T09:19:52Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:33236: runtime core not ready"938machine # [ 20.890839] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Module overlay was already loaded"939machine # [ 20.950859] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.940machine # [ 20.957311] Bridge firewalling registered941machine # [ 20.963659] k3s[842]: time="2026-10-06T09:19:52Z" level=warning msg="Failed to load kernel module iptable_nat with modprobe"942machine # [ 20.969442] k3s[842]: time="2026-10-06T09:19:52Z" level=warning msg="Failed to load kernel module iptable_filter with modprobe"943machine # [ 20.978087] k3s[842]: time="2026-10-06T09:19:52Z" level=warning msg="Failed to load kernel module nft-expr-counter with modprobe"944machine # [ 21.031736] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Set sysctl 'net/ipv4/conf/all/forwarding' to 1"945machine # [ 21.034695] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_max' to 131072"946machine # [ 21.039012] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400"947machine # [ 21.041787] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_close_wait' to 3600"948machine # [ 21.044391] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Creating k3s-cert-monitor event broadcaster"949machine # [ 21.046425] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Connecting to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"950machine # [ 21.048665] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Saving cluster bootstrap data to datastore"951machine # [ 21.050744] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Polling for API server readiness: GET /readyz failed: the server is currently unable to handle the request"952machine # [ 21.053612] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"953machine # [ 21.055783] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Connection to etcd is ready"954machine # [ 21.057458] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="ETCD server is now running"955machine # [ 21.059153] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Handling backend connection request [machine]"956machine # [ 21.060909] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"957machine # [ 21.062814] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Remotedialer connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"958machine # [ 21.064950] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=https://kubernetes.default.svc.cluster.local,k3s --authorization-mode=Node,RBAC --bind-address=127.0.0.1 --cert-dir=/var/lib/rancher/k3s/server/tls/temporary-certs --client-ca-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --egress-selector-config-file=/var/lib/rancher/k3s/server/etc/egress-selector-config.yaml --enable-admission-plugins=NodeRestriction --enable-aggregator-routing=true --enable-bootstrap-token-auth=true --etcd-servers=unix://kine.sock --kubelet-certificate-authority=/var/lib/rancher/k3s/server/tls/server-ca.crt --kubelet-client-certificate=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.crt --kubelet-client-key=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.key --kubelet-preferred-address-types=InternalIP,ExternalIP,Hostname --profiling=false --proxy-client-cert-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt --proxy-client-key-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.key --requestheader-allowed-names=system:auth-proxy --requestheader-client-ca-file=/var/lib/rancher/k3s/server/tls/request-header-ca.crt --requestheader-extra-headers-prefix=X-Remote-Extra- --requestheader-group-headers=X-Remote-Group --requestheader-username-headers=X-Remote-User --secure-port=6444 --service-account-issuer=https://kubernetes.default.svc.cluster.local --service-account-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-account-signing-key-file=/var/lib/rancher/k3s/server/tls/service.current.key --service-cluster-ip-range=10.43.0.0/16 --service-node-port-range=30000-32767 --storage-backend=etcd3 --tls-cert-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt --tls-cipher-suites=TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305,TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305 --tls-private-key-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key"959machine # [ 21.091729] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Running kube-scheduler --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --bind-address=127.0.0.1 --kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --leader-elect=false --profiling=false --secure-port=10259 --tls-cert-file=/var/lib/rancher/k3s/server/tls/kube-scheduler/kube-scheduler.crt --tls-private-key-file=/var/lib/rancher/k3s/server/tls/kube-scheduler/kube-scheduler.key"960machine # [ 21.098653] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Running kube-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --bind-address=127.0.0.1 --cluster-cidr=10.42.0.0/16 --cluster-signing-kube-apiserver-client-cert-file=/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt --cluster-signing-kube-apiserver-client-key-file=/var/lib/rancher/k3s/server/tls/client-ca.key --cluster-signing-kubelet-client-cert-file=/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt --cluster-signing-kubelet-client-key-file=/var/lib/rancher/k3s/server/tls/client-ca.key --cluster-signing-kubelet-serving-cert-file=/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt --cluster-signing-kubelet-serving-key-file=/var/lib/rancher/k3s/server/tls/server-ca.key --cluster-signing-legacy-unknown-cert-file=/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt --cluster-signing-legacy-unknown-key-file=/var/lib/rancher/k3s/server/tls/server-ca.key --configure-cloud-routes=false --controllers=*,tokencleaner,-service,-route,-cloud-node-lifecycle --kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --leader-elect=false --profiling=false --root-ca-file=/var/lib/rancher/k3s/server/tls/server-ca.crt --secure-port=10257 --service-account-private-key-file=/var/lib/rancher/k3s/server/tls/service.current.key --service-cluster-ip-range=10.43.0.0/16 --tls-cert-file=/var/lib/rancher/k3s/server/tls/kube-controller-manager/kube-controller-manager.crt --tls-private-key-file=/var/lib/rancher/k3s/server/tls/kube-controller-manager/kube-controller-manager.key --use-service-account-credentials=true"961machine # [ 21.120549] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Running cloud-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --bind-address=127.0.0.1 --cloud-config=/var/lib/rancher/k3s/server/etc/cloud-config.yaml --cloud-provider=k3s --cluster-cidr=10.42.0.0/16 --configure-cloud-routes=false --controllers=*,-route --kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --leader-elect=false --leader-elect-resource-name=k3s-cloud-controller-manager --node-status-update-frequency=1m0s --profiling=false"962machine # [ 21.128945] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"963machine # [ 21.130580] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="To join server node to cluster: k3s server -s https://10.0.2.15:6443 -t ${SERVER_NODE_TOKEN}"964machine # [ 21.132578] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"965machine # [ 21.134357] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="To join agent node to cluster: k3s agent -s https://10.0.2.15:6443 -t ${AGENT_NODE_TOKEN}"966machine # [ 21.136272] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"967machine # [ 21.137714] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Run: k3s kubectl"968machine # [ 21.138897] k3s[842]: I1006 09:19:52.900011 842 options.go:263] external host was not specified, using 10.0.2.15969machine # [ 21.140473] k3s[842]: I1006 09:19:52.907865 842 server.go:158] Version: v1.36.4+k3s1970machine # [ 21.141673] k3s[842]: I1006 09:19:52.907930 842 server.go:160] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""971machine # [ 21.168126] k3s[842]: time="2026-10-06T09:19:52Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log"972machine # [ 21.183909] k3s[842]: time="2026-10-06T09:19:53Z" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml"973machine # [ 21.196093] k3s[842]: time="2026-10-06T09:19:53Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:51794: runtime core not ready"974machine # [ 21.384113] k3s[842]: time="2026-10-06T09:19:53Z" level=info msg="Running kube-proxy --cluster-cidr=10.42.0.0/16 --conntrack-max-per-core=0 --conntrack-tcp-timeout-close-wait=0s --conntrack-tcp-timeout-established=0s --healthz-bind-address=127.0.0.1 --hostname-override=machine --kubeconfig=/var/lib/rancher/k3s/agent/kubeproxy.kubeconfig --proxy-mode=iptables"975machine # [ 21.521319] k3s[842]: I1006 09:19:53.345178 842 shared_informer.go:381] "Waiting for caches to sync" controller="node_authorizer"976machine # [ 21.523183] k3s[842]: E1006 09:19:53.345566 842 options.go:205] The manifest file is empty, ignoring.977machine # [ 21.544069] k3s[842]: I1006 09:19:53.369692 842 shared_informer.go:402] "Waiting for caches to sync"978machine # [ 21.553474] k3s[842]: I1006 09:19:53.378546 842 shared_informer.go:402] "Waiting for caches to sync"979machine # [ 21.555505] k3s[842]: I1006 09:19:53.381389 842 plugins.go:157] Loaded 15 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,PodGroupProtection,RuntimeClass,DefaultIngressClass,PodTopologyLabels,MutatingAdmissionPolicy,MutatingAdmissionWebhook.980machine # [ 21.561067] k3s[842]: I1006 09:19:53.381460 842 plugins.go:160] Loaded 17 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,PodSecurity,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,ClusterTrustBundleAttest,CertificateSubjectRestriction,PodGroupWorkloadExists,NodeDeclaredFeatureValidator,JobValidation,PodResizeValidator,ValidatingAdmissionPolicy,ValidatingAdmissionWebhook,ResourceQuota.981machine # [ 21.567014] k3s[842]: I1006 09:19:53.382456 842 instance.go:240] Using reconciler: lease982machine # [ 21.569115] k3s[842]: I1006 09:19:53.389963 842 handler.go:304] Adding GroupVersion apiextensions.k8s.io v1 to ResourceManager983machine # [ 21.575056] k3s[842]: W1006 09:19:53.390105 842 genericapiserver.go:798] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources.984machine # [ 21.578047] k3s[842]: I1006 09:19:53.394903 842 cidrallocator.go:198] starting ServiceCIDR Allocator Controller985machine # [ 21.644118] rustfs-setup-start[920]: mb s3://niks3986machine # [ 21.650041] systemd[1]: Finished Setup RustFS bucket.987machine # [ 21.653732] k3s[842]: I1006 09:19:53.479463 842 handler.go:304] Adding GroupVersion v1 to ResourceManager988machine # [ 21.656200] k3s[842]: I1006 09:19:53.482090 842 apis.go:112] API group "internal.apiserver.k8s.io" is not enabled, skipping.989machine # [ 21.704857] k3s[842]: I1006 09:19:53.530738 842 apis.go:112] API group "storagemigration.k8s.io" is not enabled, skipping.990machine # [ 21.778759] k3s[842]: I1006 09:19:53.604444 842 handler.go:304] Adding GroupVersion authentication.k8s.io v1 to ResourceManager991machine # [ 21.780550] k3s[842]: W1006 09:19:53.604485 842 genericapiserver.go:798] Skipping API authentication.k8s.io/v1beta1 because it has no resources.992machine # [ 21.782299] k3s[842]: W1006 09:19:53.604497 842 genericapiserver.go:798] Skipping API authentication.k8s.io/v1alpha1 because it has no resources.993machine # [ 21.788153] k3s[842]: I1006 09:19:53.605041 842 handler.go:304] Adding GroupVersion authorization.k8s.io v1 to ResourceManager994machine # [ 21.789839] k3s[842]: W1006 09:19:53.605056 842 genericapiserver.go:798] Skipping API authorization.k8s.io/v1beta1 because it has no resources.995machine # [ 21.791582] k3s[842]: I1006 09:19:53.605907 842 handler.go:304] Adding GroupVersion autoscaling v2 to ResourceManager996machine # [ 21.794523] k3s[842]: I1006 09:19:53.606716 842 handler.go:304] Adding GroupVersion autoscaling v1 to ResourceManager997machine # [ 21.796179] k3s[842]: I1006 09:19:53.608108 842 handler.go:304] Adding GroupVersion batch v1 to ResourceManager998machine # [ 21.797695] k3s[842]: W1006 09:19:53.608126 842 genericapiserver.go:798] Skipping API batch/v1beta1 because it has no resources.999machine # [ 21.799444] k3s[842]: I1006 09:19:53.608996 842 handler.go:304] Adding GroupVersion certificates.k8s.io v1 to ResourceManager1000machine # [ 21.801169] k3s[842]: W1006 09:19:53.609013 842 genericapiserver.go:798] Skipping API certificates.k8s.io/v1beta1 because it has no resources.1001machine # [ 21.803101] k3s[842]: W1006 09:19:53.609021 842 genericapiserver.go:798] Skipping API certificates.k8s.io/v1alpha1 because it has no resources.1002machine # [ 21.806127] k3s[842]: I1006 09:19:53.610904 842 handler.go:304] Adding GroupVersion coordination.k8s.io v1 to ResourceManager1003machine # [ 21.807669] k3s[842]: W1006 09:19:53.610929 842 genericapiserver.go:798] Skipping API coordination.k8s.io/v1beta1 because it has no resources.1004machine # [ 21.810259] k3s[842]: W1006 09:19:53.610936 842 genericapiserver.go:798] Skipping API coordination.k8s.io/v1alpha2 because it has no resources.1005machine # [ 21.812407] k3s[842]: I1006 09:19:53.611585 842 handler.go:304] Adding GroupVersion discovery.k8s.io v1 to ResourceManager1006machine # [ 21.814035] k3s[842]: W1006 09:19:53.611608 842 genericapiserver.go:798] Skipping API discovery.k8s.io/v1beta1 because it has no resources.1007machine # [ 21.818255] k3s[842]: I1006 09:19:53.615329 842 handler.go:304] Adding GroupVersion networking.k8s.io v1 to ResourceManager1008machine # [ 21.820073] k3s[842]: W1006 09:19:53.615354 842 genericapiserver.go:798] Skipping API networking.k8s.io/v1beta1 because it has no resources.1009machine # [ 21.821864] k3s[842]: I1006 09:19:53.615793 842 handler.go:304] Adding GroupVersion node.k8s.io v1 to ResourceManager1010machine # [ 21.823324] k3s[842]: W1006 09:19:53.615806 842 genericapiserver.go:798] Skipping API node.k8s.io/v1beta1 because it has no resources.1011machine # [ 21.825088] k3s[842]: W1006 09:19:53.615812 842 genericapiserver.go:798] Skipping API node.k8s.io/v1alpha1 because it has no resources.1012machine # [ 21.826878] k3s[842]: I1006 09:19:53.616582 842 handler.go:304] Adding GroupVersion policy v1 to ResourceManager1013machine # [ 21.828318] k3s[842]: W1006 09:19:53.616607 842 genericapiserver.go:798] Skipping API policy/v1beta1 because it has no resources.1014machine # [ 21.829866] k3s[842]: I1006 09:19:53.618271 842 handler.go:304] Adding GroupVersion rbac.authorization.k8s.io v1 to ResourceManager1015machine # [ 21.831635] k3s[842]: W1006 09:19:53.618289 842 genericapiserver.go:798] Skipping API rbac.authorization.k8s.io/v1beta1 because it has no resources.1016machine # [ 21.833513] k3s[842]: W1006 09:19:53.618298 842 genericapiserver.go:798] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources.1017machine # [ 21.835336] k3s[842]: I1006 09:19:53.618792 842 handler.go:304] Adding GroupVersion scheduling.k8s.io v1 to ResourceManager1018machine # [ 21.836904] k3s[842]: W1006 09:19:53.618805 842 genericapiserver.go:798] Skipping API scheduling.k8s.io/v1beta1 because it has no resources.1019machine # [ 21.838561] k3s[842]: W1006 09:19:53.618812 842 genericapiserver.go:798] Skipping API scheduling.k8s.io/v1alpha2 because it has no resources.1020machine # [ 21.840289] k3s[842]: I1006 09:19:53.623909 842 handler.go:304] Adding GroupVersion storage.k8s.io v1 to ResourceManager1021machine # [ 21.841799] k3s[842]: W1006 09:19:53.624162 842 genericapiserver.go:798] Skipping API storage.k8s.io/v1beta1 because it has no resources.1022machine # [ 21.843509] k3s[842]: W1006 09:19:53.624178 842 genericapiserver.go:798] Skipping API storage.k8s.io/v1alpha1 because it has no resources.1023machine # [ 21.845305] k3s[842]: I1006 09:19:53.625304 842 handler.go:304] Adding GroupVersion flowcontrol.apiserver.k8s.io v1 to ResourceManager1024machine # [ 21.848172] k3s[842]: W1006 09:19:53.625365 842 genericapiserver.go:798] Skipping API flowcontrol.apiserver.k8s.io/v1beta3 because it has no resources.1025machine # [ 21.850000] k3s[842]: W1006 09:19:53.625375 842 genericapiserver.go:798] Skipping API flowcontrol.apiserver.k8s.io/v1beta2 because it has no resources.1026machine # [ 21.856080] k3s[842]: W1006 09:19:53.625380 842 genericapiserver.go:798] Skipping API flowcontrol.apiserver.k8s.io/v1beta1 because it has no resources.1027machine # [ 21.857937] k3s[842]: I1006 09:19:53.630972 842 handler.go:304] Adding GroupVersion apps v1 to ResourceManager1028machine # [ 21.859360] k3s[842]: W1006 09:19:53.630996 842 genericapiserver.go:798] Skipping API apps/v1beta2 because it has no resources.1029machine # [ 21.860987] k3s[842]: W1006 09:19:53.631004 842 genericapiserver.go:798] Skipping API apps/v1beta1 because it has no resources.1030machine # [ 21.862515] k3s[842]: I1006 09:19:53.634636 842 handler.go:304] Adding GroupVersion admissionregistration.k8s.io v1 to ResourceManager1031machine # [ 21.868204] k3s[842]: W1006 09:19:53.634661 842 genericapiserver.go:798] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources.1032machine # [ 21.869999] k3s[842]: W1006 09:19:53.634668 842 genericapiserver.go:798] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources.1033machine # [ 21.871809] k3s[842]: I1006 09:19:53.635266 842 handler.go:304] Adding GroupVersion events.k8s.io v1 to ResourceManager1034machine # [ 21.874265] k3s[842]: W1006 09:19:53.635278 842 genericapiserver.go:798] Skipping API events.k8s.io/v1beta1 because it has no resources.1035machine # [ 21.875961] k3s[842]: I1006 09:19:53.638238 842 handler.go:304] Adding GroupVersion resource.k8s.io v1 to ResourceManager1036machine # [ 21.880148] k3s[842]: W1006 09:19:53.638274 842 genericapiserver.go:798] Skipping API resource.k8s.io/v1beta2 because it has no resources.1037machine # [ 21.881854] k3s[842]: W1006 09:19:53.638283 842 genericapiserver.go:798] Skipping API resource.k8s.io/v1beta1 because it has no resources.1038machine # [ 21.883531] k3s[842]: W1006 09:19:53.638289 842 genericapiserver.go:798] Skipping API resource.k8s.io/v1alpha3 because it has no resources.1039machine # [ 21.887717] k3s[842]: I1006 09:19:53.641740 842 handler.go:304] Adding GroupVersion apiregistration.k8s.io v1 to ResourceManager1040machine # [ 21.889428] k3s[842]: W1006 09:19:53.641798 842 genericapiserver.go:798] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources.1041machine # [ 22.216711] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="containerd is now running"1042machine # [ 22.220073] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/nixos/lf2s5pc8i15d9jlqqva8rkqqip46lm3k-k3s-airgap-images-arm64.tar.zst"1043machine # [ 22.478788] k3s[842]: I1006 09:19:54.304509 842 dynamic_serving_content.go:135] "Starting controller" name="serving-cert::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key"1044machine # [ 22.481949] k3s[842]: I1006 09:19:54.305029 842 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"1045machine # [ 22.486191] k3s[842]: I1006 09:19:54.305417 842 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"1046machine # [ 22.488352] k3s[842]: I1006 09:19:54.305819 842 secure_serving.go:214] Serving securely on 127.0.0.1:64441047machine # [ 22.489675] k3s[842]: I1006 09:19:54.306067 842 tlsconfig.go:243] "Starting DynamicServingCertificateController"1048machine # [ 22.491200] k3s[842]: I1006 09:19:54.308881 842 aggregator.go:185] waiting for initial CRD sync...1049machine # [ 22.496304] k3s[842]: I1006 09:19:54.308924 842 controller.go:87] "Starting OpenAPI AggregationController"1050machine # [ 22.497669] k3s[842]: I1006 09:19:54.309021 842 system_namespaces_controller.go:66] Starting system namespaces controller1051machine # [ 22.499231] k3s[842]: I1006 09:19:54.309044 842 dynamic_serving_content.go:135] "Starting controller" name="aggregator-proxy-cert::/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt::/var/lib/rancher/k3s/server/tls/client-auth-proxy.key"1052machine # [ 22.504255] k3s[842]: I1006 09:19:54.310241 842 controller.go:89] "Starting OpenAPI V3 AggregationController"1053machine # [ 22.505633] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Starting apiserver lease garbage collector" logger=k3s1054machine # [ 22.507047] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Waiting for caches to sync" logger=k3s1055machine # [ 22.508323] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Starting legacy_token_tracking_controller" logger=k3s1056machine # [ 22.509719] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Waiting for caches to sync" logger=k3s1057machine # [ 22.510951] k3s[842]: I1006 09:19:54.311281 842 cluster_authentication_trust_controller.go:459] Starting cluster_authentication_trust_controller controller1058machine # [ 22.516227] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Waiting for caches to sync" logger=k3s1059machine # [ 22.517500] k3s[842]: I1006 09:19:54.311343 842 controller.go:113] "Deleting old lease on startup" lease="kube-system/apiserver-ik4pcwfs7qgdl76byc4pomgvia"1060machine # [ 22.519333] k3s[842]: I1006 09:19:54.312161 842 storage_readiness_hook.go:70] Storage is ready for all registered resources1061machine # [ 22.520884] k3s[842]: I1006 09:19:54.312217 842 local_available_controller.go:156] Starting LocalAvailability controller1062machine # [ 22.524117] k3s[842]: I1006 09:19:54.312227 842 cache.go:32] Waiting for caches to sync for LocalAvailability controller1063machine # [ 22.525653] k3s[842]: I1006 09:19:54.312251 842 apiservice_controller.go:100] Starting APIServiceRegistrationController1064machine # [ 22.527120] k3s[842]: I1006 09:19:54.312265 842 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller1065machine # [ 22.532161] k3s[842]: I1006 09:19:54.312436 842 remote_available_controller.go:434] Starting RemoteAvailability controller1066machine # [ 22.533706] k3s[842]: I1006 09:19:54.312447 842 cache.go:32] Waiting for caches to sync for RemoteAvailability controller1067machine # [ 22.535195] k3s[842]: I1006 09:19:54.312546 842 apf_controller.go:377] Starting API Priority and Fairness config controller1068machine # [ 22.536757] k3s[842]: I1006 09:19:54.313342 842 repairip.go:210] Starting ipallocator-repair-controller1069machine # [ 22.538034] k3s[842]: I1006 09:19:54.313367 842 shared_informer.go:381] "Waiting for caches to sync" controller="ipallocator-repair-controller"1070machine # [ 22.539826] k3s[842]: I1006 09:19:54.313841 842 crdregistration_controller.go:114] Starting crd-autoregister controller1071machine # [ 22.541385] k3s[842]: I1006 09:19:54.313855 842 shared_informer.go:381] "Waiting for caches to sync" controller="crd-autoregister"1072machine # [ 22.543015] k3s[842]: I1006 09:19:54.323283 842 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"1073machine # [ 22.547232] k3s[842]: I1006 09:19:54.328285 842 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"1074machine # [ 22.551156] k3s[842]: I1006 09:19:54.328866 842 controller.go:142] Starting OpenAPI controller1075machine # [ 22.552536] k3s[842]: I1006 09:19:54.328906 842 controller.go:90] Starting OpenAPI V3 controller1076machine # [ 22.553749] k3s[842]: I1006 09:19:54.328928 842 naming_controller.go:305] Starting NamingConditionController1077machine # [ 22.555179] k3s[842]: I1006 09:19:54.329059 842 nonstructuralschema_controller.go:202] Starting NonStructuralSchemaConditionController1078machine # [ 22.560101] k3s[842]: I1006 09:19:54.329095 842 apiapproval_controller.go:196] Starting KubernetesAPIApprovalPolicyConformantConditionController1079machine # [ 22.561983] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Starting CRDFinalizer" logger=k3s1080machine # [ 22.563355] k3s[842]: I1006 09:19:54.329151 842 customresource_discovery_controller.go:294] Starting DiscoveryController1081machine # [ 22.564970] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg=Starting controller=kubernetes-service-cidr-controller logger=k3s1082machine # [ 22.566496] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Waiting for caches to sync" logger=k3s1083machine # [ 22.690024] k3s[842]: I1006 09:19:54.515857 842 shared_informer.go:388] "Caches are synced" controller="crd-autoregister"1084machine # [ 22.691797] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Caches are synced" logger=k3s1085machine # [ 22.696215] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Caches are synced" logger=k3s1086machine # [ 22.697459] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Caches are synced" logger=k3s1087machine # [ 22.698615] k3s[842]: I1006 09:19:54.517613 842 cache.go:39] Caches are synced for LocalAvailability controller1088machine # [ 22.700099] k3s[842]: I1006 09:19:54.517643 842 cache.go:39] Caches are synced for APIServiceRegistrationController controller1089machine # [ 22.701643] k3s[842]: I1006 09:19:54.517675 842 cache.go:39] Caches are synced for RemoteAvailability controller1090machine # [ 22.703048] k3s[842]: I1006 09:19:54.517704 842 apf_controller.go:382] Running API Priority and Fairness config worker1091machine # [ 22.707061] k3s[842]: I1006 09:19:54.517713 842 apf_controller.go:385] Running API Priority and Fairness periodic rebalancing process1092machine # [ 22.708887] k3s[842]: I1006 09:19:54.517869 842 shared_informer.go:388] "Caches are synced" controller="ipallocator-repair-controller"1093machine # [ 22.710482] k3s[842]: I1006 09:19:54.517927 842 aggregator.go:187] initial CRD sync complete...1094machine # [ 22.711676] k3s[842]: I1006 09:19:54.517938 842 autoregister_controller.go:144] Starting autoregister controller1095machine # [ 22.713180] k3s[842]: I1006 09:19:54.517946 842 cache.go:32] Waiting for caches to sync for autoregister controller1096machine # [ 22.714563] k3s[842]: I1006 09:19:54.517954 842 cache.go:39] Caches are synced for autoregister controller1097machine # [ 22.716068] k3s[842]: I1006 09:19:54.518770 842 handler_discovery.go:459] Starting ResourceDiscoveryManager1098machine # [ 22.717395] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Caches are synced" logger=k3s1099machine # [ 22.718536] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Creating default ServiceCIDR" CIDRs="[10.43.0.0/16]" logger=k3s1100machine # [ 22.722308] k3s[842]: I1006 09:19:54.548182 842 shared_informer.go:388] "Caches are synced" controller="node_authorizer"1101machine # [ 22.747457] k3s[842]: E1006 09:19:54.573256 842 controller.go:201] "Failed to ensure lease exists, will retry" err="namespaces \"kube-system\" not found" interval="200ms"1102machine # [ 22.754183] k3s[842]: I1006 09:19:54.576905 842 shared_informer.go:409] "Caches are synced"1103machine # [ 22.755460] k3s[842]: I1006 09:19:54.576955 842 policy_source.go:248] refreshing policies1104machine # [ 22.756679] k3s[842]: I1006 09:19:54.578805 842 shared_informer.go:409] "Caches are synced"1105machine # [ 22.757833] k3s[842]: I1006 09:19:54.578831 842 policy_source.go:248] refreshing policies1106machine # [ 22.760393] k3s[842]: E1006 09:19:54.585249 842 controller.go:95] Unable to perform initial Kubernetes service initialization: namespaces "default" not found1107machine # [ 22.762356] k3s[842]: time="2026-10-06T09:19:54Z" level=error msg="Error while syncing ConfigMap" configmap=kube-system/kube-apiserver-legacy-service-account-token-tracking error="namespaces \"kube-system\" not found" logger=k3s/UnhandledError1108machine # [ 22.813918] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Setting default ServiceCIDR condition Ready to True" logger=k3s1109machine # [ 22.840965] k3s[842]: I1006 09:19:54.666841 842 cidrallocator.go:302] created ClusterIP allocator for Service CIDR 10.43.0.0/161110machine # [ 22.854867] k3s[842]: I1006 09:19:54.680763 842 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161111machine # [ 22.857623] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Setting default ServiceCIDR condition Ready to True" logger=k3s1112machine # [ 22.959540] k3s[842]: I1006 09:19:54.785284 842 controller.go:667] quota admission added evaluator for: leases.coordination.k8s.io1113machine # [ 23.040538] k3s[842]: time="2026-10-06T09:19:54Z" level=info msg="Polling for API server readiness: GET /readyz failed: unknown"1114machine # [ 23.493407] k3s[842]: I1006 09:19:55.318103 842 storage_scheduling.go:137] created PriorityClass system-node-critical with value 20000010001115machine # [ 23.501344] k3s[842]: I1006 09:19:55.327175 842 storage_scheduling.go:137] created PriorityClass system-cluster-critical with value 20000000001116machine # [ 23.503588] k3s[842]: I1006 09:19:55.327207 842 storage_scheduling.go:153] all system priority classes are created successfully or already exist.1117machine # [ 25.044332] k3s[842]: time="2026-10-06T09:19:56Z" level=info msg="Polling for API server readiness: GET /readyz failed: an error on the server (\"[+]ping ok\\n[+]log ok\\n[+]etcd ok\\n[+]etcd-readiness ok\\n[+]informer-sync ok\\n[+]poststarthook/start-apiserver-admission-initializer ok\\n[+]poststarthook/generic-apiserver-start-informers ok\\n[+]poststarthook/priority-and-fairness-config-consumer ok\\n[+]poststarthook/priority-and-fairness-filter ok\\n[+]poststarthook/storage-object-count-tracker-hook ok\\n[+]poststarthook/start-apiextensions-informers ok\\n[+]poststarthook/start-apiextensions-controllers ok\\n[+]poststarthook/crd-informer-synced ok\\n[+]poststarthook/start-system-namespaces-controller ok\\n[+]poststarthook/peer-endpoint-reconciler-controller ok\\n[+]poststarthook/start-cluster-authentication-info-controller ok\\n[+]poststarthook/start-kube-apiserver-identity-lease-controller ok\\n[+]poststarthook/start-kube-apiserver-identity-lease-garbage-collector ok\\n[+]poststarthook/storage-readiness ok\\n[+]poststarthook/start-legacy-token-tracking-controller ok\\n[+]poststarthook/start-service-ip-repair-controllers ok\\n[-]poststarthook/rbac/bootstrap-roles failed: reason withheld\\n[+]poststarthook/scheduling/bootstrap-system-priority-classes ok\\n[+]poststarthook/priority-and-fairness-config-producer ok\\n[+]poststarthook/bootstrap-controller ok\\n[+]poststarthook/start-kubernetes-service-cidr-controller ok\\n[+]poststarthook/aggregator-reload-proxy-client-cert ok\\n[+]poststarthook/start-kube-aggregator-informers ok\\n[+]poststarthook/apiservice-status-local-available-controller ok\\n[+]poststarthook/apiservice-status-remote-available-controller ok\\n[+]poststarthook/apiservice-registration-controller ok\\n[+]poststarthook/apiservice-discovery-controller ok\\n[+]poststarthook/kube-apiserver-autoregistration ok\\n[+]autoregister-completion ok\\n[+]poststarthook/apiservice-openapi-controller ok\\n[+]poststarthook/apiservice-openapiv3-controller ok\\n[+]shutdown ok\\nreadyz check failed\") has prevented the request from succeeding"1118machine # [ 25.068941] k3s[842]: I1006 09:19:56.878045 842 controller.go:667] quota admission added evaluator for: roles.rbac.authorization.k8s.io1119machine # [ 25.100938] k3s[842]: I1006 09:19:56.926615 842 controller.go:667] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io1120machine # [ 25.273988] k3s[842]: I1006 09:19:57.099793 842 alloc.go:329] "allocated clusterIPs" service="default/kubernetes" clusterIPs={"IPv4":"10.43.0.1"}1121machine # [ 25.283218] k3s[842]: W1006 09:19:57.108760 842 lease.go:265] Resetting endpoints for master service "kubernetes" to [10.0.2.15]1122machine # [ 25.286507] k3s[842]: I1006 09:19:57.112103 842 controller.go:667] quota admission added evaluator for: endpoints1123machine # [ 25.295033] k3s[842]: I1006 09:19:57.120782 842 controller.go:667] quota admission added evaluator for: endpointslices.discovery.k8s.io1124machine # [ 25.795847] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported docker.io/rancher/klipper-helm:v0.13.3-build20260727"1125machine # [ 25.800188] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Tagged docker.io/rancher/klipper-helm@sha256:5425a2b4613d2458dbdff99218e8d487ebb59c20e7a941f061c0777070f0aac1"1126machine # [ 25.803902] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported docker.io/rancher/klipper-lb:v0.4.17"1127machine # [ 25.807451] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Tagged docker.io/rancher/klipper-lb@sha256:910944bb0bd94f060a82a56ca1ea1c577d3e49b3473a093a47a985f32e92d94a"1128machine # [ 25.809928] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported docker.io/rancher/local-path-provisioner:v0.0.37"1129machine # [ 25.813948] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Tagged docker.io/rancher/local-path-provisioner@sha256:e757967a5ec338f6a9b371c5a9688bedaa8c3578ea3dd4db329ea0084be0a86f"1130machine # [ 25.816622] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported docker.io/rancher/mirrored-coredns-coredns:1.14.6"1131machine # [ 25.819598] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Tagged docker.io/rancher/mirrored-coredns-coredns@sha256:900f9c109f7a33545d3c811516e8376df9019147b750f5ce3e254468769176ea"1132machine # [ 25.822431] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported docker.io/rancher/mirrored-library-busybox:1.37.0"1133machine # [ 25.824264] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Tagged docker.io/rancher/mirrored-library-busybox@sha256:101b4afd76732482eff9b95cae5f94bcf295e521fbec4e01b69c5421f3f3f3e5"1134machine # [ 25.826818] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported docker.io/rancher/mirrored-library-traefik:3.7.8"1135machine # [ 25.829492] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Tagged docker.io/rancher/mirrored-library-traefik@sha256:4299bbed850421258fc5448c2e0e6ad350981d4d335a68de11b92448aedbefe5"1136machine # [ 25.831847] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported docker.io/rancher/mirrored-metrics-server:v0.9.0"1137machine # [ 25.833592] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Tagged docker.io/rancher/mirrored-metrics-server@sha256:d9862115e7c7881280d3d75ca26bda8ffc0fc213315979575bf23ce9826205c0"1138machine # [ 25.835864] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported docker.io/rancher/mirrored-pause:3.10.2"1139machine # [ 25.837394] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Tagged docker.io/rancher/mirrored-pause@sha256:f548e0e8e3dc1896ca956272154dde3314e8cc4fde0a57577ee9fa1c63f5baf4"1140machine # [ 25.974408] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Imported 8 images from /var/lib/rancher/k3s/agent/images/nixos/lf2s5pc8i15d9jlqqva8rkqqip46lm3k-k3s-airgap-images-arm64.tar.zst in 3.75499498s"1141machine # [ 25.979238] k3s[842]: time="2026-10-06T09:19:57Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/nixos/x3a00h11n7d3hrj0mbrsbzxjm1q11i65-niks3-server.tar"1142machine # [ 26.223983] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Running kubelet --cloud-provider=external --config-dir=/var/lib/rancher/k3s/agent/etc/kubelet.conf.d --containerd=/run/k3s/containerd/containerd.sock --hostname-override=machine --kubeconfig=/var/lib/rancher/k3s/agent/kubelet.kubeconfig --node-ip=10.0.2.15,fec0::87bf:b810:8c62:a860 --node-labels= --read-only-port=0"1143machine # [ 26.398094] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Imported docker.io/library/niks3-server:1.4.0-aarch64-linux"1144machine # [ 26.401786] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Tagged docker.io/library/niks3-server@sha256:fb0febb4b5a3e46b7377ab616004c573d3a608a4837715dfb013b0f1070567e5"1145machine # [ 26.418932] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Imported 1 images from /var/lib/rancher/k3s/agent/images/nixos/x3a00h11n7d3hrj0mbrsbzxjm1q11i65-niks3-server.tar in 444.25292ms"1146machine # [ 27.046160] k3s[842]: Flag --containerd has been deprecated, This is a cadvisor flag that was mistakenly registered with the Kubelet. Due to legacy concerns, it will follow the standard CLI deprecation timeline before being removed.1147machine # [ 27.062337] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Waiting for untainted node"1148machine # [ 27.064876] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Creating k3s-supervisor event broadcaster"1149machine # [ 27.069049] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Kube API server is now running"1150machine # [ 27.070968] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="k3s is up and running"1151machine # [ 27.072720] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Node and Certificate Authority certificates managed by k3s are OK" object=machine reason=CertificateExpirationOK type=Normal1152machine # [ 27.078193] systemd[1]: Started k3s service.1153machine # [ 27.079249] systemd[1]: Reached target Multi-User System.1154machine # [ 27.080547] systemd[1]: Startup finished in 772ms (kernel) + 3.855s (initrd) + 22.440s (userspace) = 27.068s.1155machine # [ 27.088102] k3s[842]: I1006 09:19:58.912987 842 server.go:541] "Kubelet version" kubeletVersion="v1.36.4+k3s1"1156machine # [ 27.090185] k3s[842]: I1006 09:19:58.913052 842 server.go:543] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1157machine # [ 27.096174] k3s[842]: I1006 09:19:58.913093 842 watchdog_linux.go:94] "Systemd watchdog is not enabled"1158machine # [ 27.098141] k3s[842]: I1006 09:19:58.913120 842 watchdog_linux.go:137] "Systemd watchdog is not enabled or the interval is invalid, so health checking will not be started."1159machine # [ 27.101264] k3s[842]: I1006 09:19:58.925902 842 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt"1160machine # [ 27.109398] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Creating embedded CRD addons.k3s.cattle.io"1161machine # [ 27.118212] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Creating embedded CRD etcdsnapshotfiles.k3s.cattle.io"1162machine # [ 27.127799] k3s[842]: I1006 09:19:58.953698 842 server.go:1444] "Using cgroup driver setting received from the CRI runtime" cgroupDriver="systemd"1163machine # [ 27.132228] k3s[842]: E1006 09:19:58.955236 842 options.go:205] The manifest file is empty, ignoring.1164machine # [ 27.135417] k3s[842]: I1006 09:19:58.960662 842 controllermanager.go:204] "Starting" version="v1.36.4+k3s1"1165machine # [ 27.138481] k3s[842]: I1006 09:19:58.960697 842 controllermanager.go:206] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1166machine # [ 27.140875] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Creating embedded CRD helmchartconfigs.helm.cattle.io"1167machine # [ 27.147063] k3s[842]: I1006 09:19:58.971517 842 server.go:804] "--cgroups-per-qos enabled, but --cgroup-root was not specified. Defaulting to /"1168machine # [ 27.149552] k3s[842]: I1006 09:19:58.971571 842 server.go:865] "NoSwap is set due to memorySwapBehavior not specified" memorySwapBehavior="" FailSwapOn=false1169machine # [ 27.151807] k3s[842]: I1006 09:19:58.971994 842 container_manager_linux.go:273] "Container manager verified user specified cgroup-root exists" cgroupRoot=[]1170machine # [ 27.158436] k3s[842]: I1006 09:19:58.972025 842 container_manager_linux.go:278] "Creating Container Manager object based on Node Config" nodeConfig={"NodeName":"machine","RuntimeCgroupsName":"","SystemCgroupsName":"","KubeletCgroupsName":"","KubeletOOMScoreAdj":-999,"ContainerRuntime":"","CgroupsPerQOS":true,"CgroupRoot":"/","CgroupDriver":"systemd","KubeletRootDir":"/var/lib/kubelet","ProtectKernelDefaults":false,"KubeReservedCgroupName":"","SystemReservedCgroupName":"","ReservedSystemCPUs":{},"EnforceNodeAllocatable":{"pods":{}},"KubeReserved":null,"SystemReserved":null,"HardEvictionThresholds":[{"Signal":"imagefs.available","Operator":"LessThan","Value":{"Quantity":null,"Percentage":0.05},"GracePeriod":0,"MinReclaim":null},{"Signal":"nodefs.available","Operator":"LessThan","Value":{"Quantity":null,"Percentage":0.05},"GracePeriod":0,"MinReclaim":null}],"QOSReserved":{},"CPUManagerPolicy":"none","CPUManagerPolicyOptions":null,"TopologyManagerScope":"container","CPUManagerReconcilePeriod":10000000000,"MemoryManagerPolicy":"None","MemoryManagerReservedMemory":null,"MemoryReservationPolicy":"None","PodPidsLimit":-1,"EnforceCPULimits":true,"CPUCFSQuotaPeriod":100000000,"TopologyManagerPolicy":"none","TopologyManagerPolicyOptions":null,"CgroupVersion":2}1171machine # [ 27.180315] k3s[842]: I1006 09:19:58.972286 842 topology_manager.go:172] "Creating topology manager with none policy"1172machine # [ 27.181858] k3s[842]: I1006 09:19:58.972302 842 container_manager_linux.go:309] "Creating device plugin manager"1173machine # [ 27.183334] k3s[842]: I1006 09:19:58.972416 842 container_manager_linux.go:318] "Creating Dynamic Resource Allocation (DRA) manager"1174machine # [ 27.185237] k3s[842]: time="2026-10-06T09:19:58Z" level=info msg="Creating embedded CRD helmcharts.helm.cattle.io"1175machine # [ 27.186749] k3s[842]: I1006 09:19:58.987919 842 secure_serving.go:214] Serving securely on 127.0.0.1:102571176machine # [ 27.188609] k3s[842]: I1006 09:19:58.988772 842 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1177machine # [ 27.190183] k3s[842]: I1006 09:19:58.988795 842 shared_informer.go:402] "Waiting for caches to sync"1178machine # [ 27.191458] k3s[842]: I1006 09:19:58.988825 842 dynamic_serving_content.go:135] "Starting controller" name="serving-cert::/var/lib/rancher/k3s/server/tls/kube-controller-manager/kube-controller-manager.crt::/var/lib/rancher/k3s/server/tls/kube-controller-manager/kube-controller-manager.key"1179machine # [ 27.195097] k3s[842]: I1006 09:19:58.988966 842 tlsconfig.go:243] "Starting DynamicServingCertificateController"1180machine # [ 27.196565] k3s[842]: I1006 09:19:58.989373 842 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1181machine # [ 27.198893] k3s[842]: I1006 09:19:58.989390 842 shared_informer.go:402] "Waiting for caches to sync"1182machine # [ 27.200227] k3s[842]: I1006 09:19:58.989416 842 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1183machine # [ 27.202532] k3s[842]: I1006 09:19:58.989443 842 shared_informer.go:402] "Waiting for caches to sync"1184machine # [ 27.203794] k3s[842]: I1006 09:19:59.001212 842 state_mem.go:45] "Initialized" logger="CPUManager state memory"1185machine # [ 27.205258] k3s[842]: I1006 09:19:59.001429 842 kubelet.go:485] "Attempting to sync node with API server"1186machine # [ 27.206559] k3s[842]: I1006 09:19:59.001445 842 kubelet.go:386] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests"1187machine # [ 27.208200] k3s[842]: I1006 09:19:59.001467 842 kubelet.go:397] "Adding apiserver pod source"1188machine # [ 27.209357] k3s[842]: I1006 09:19:59.001482 842 apiserver.go:41] "Waiting for node sync before watching apiserver pods"1189machine # [ 27.210812] k3s[842]: I1006 09:19:59.002373 842 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1190machine # [ 27.212329] k3s[842]: I1006 09:19:59.036070 842 kuberuntime_manager.go:308] "Container runtime initialized" containerRuntime="containerd" version="2.3.4-k3s1.36" apiVersion="v1"1191machine # [ 27.220129] k3s[842]: I1006 09:19:59.041380 842 kubelet.go:1002] "Not starting ClusterTrustBundle informer because we are in static kubelet mode or the ClusterTrustBundleProjection featuregate is disabled"1192machine # [ 27.222566] k3s[842]: I1006 09:19:59.041411 842 kubelet.go:1029] "Not starting PodCertificateRequest manager because we are in static kubelet mode or the PodCertificateProjection feature gate is disabled"1193machine # [ 27.225356] k3s[842]: W1006 09:19:59.041502 842 probe.go:275] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating.1194machine # [ 27.230845] k3s[842]: I1006 09:19:59.056648 842 server.go:1280] "Started kubelet"1195machine # [ 27.234349] k3s[842]: I1006 09:19:59.060243 842 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1196machine # [ 27.236500] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Waiting for CRD helmchartconfigs.helm.cattle.io to become available"1197machine # [ 27.238109] k3s[842]: I1006 09:19:59.062353 842 fs_resource_analyzer.go:69] "Starting FS ResourceAnalyzer"1198machine # [ 27.239446] k3s[842]: I1006 09:19:59.063049 842 server.go:193] "Starting to listen" address="0.0.0.0" port=102501199machine # [ 27.241226] k3s[842]: I1006 09:19:59.064138 842 server.go:354] "Adding debug handlers to kubelet server"1200machine # [ 27.243241] k3s[842]: I1006 09:19:59.065458 842 ratelimit.go:56] "Setting rate limiting for endpoint" service="podresources" qps=100 burstTokens=101201machine # [ 27.245289] k3s[842]: I1006 09:19:59.065563 842 server_v1.go:49] "podresources" method="list" useActivePods=true1202machine # [ 27.248209] k3s[842]: I1006 09:19:59.065783 842 server.go:264] "Starting to serve the podresources API" endpoint="unix:/var/lib/kubelet/pod-resources/kubelet.sock"1203machine # [ 27.250292] k3s[842]: I1006 09:19:59.067627 842 dynamic_serving_content.go:135] "Starting controller" name="kubelet-server-cert-files::/var/lib/rancher/k3s/agent/serving-kubelet.crt::/var/lib/rancher/k3s/agent/serving-kubelet.key"1204machine # [ 27.253101] k3s[842]: I1006 09:19:59.068010 842 tlsconfig.go:243] "Starting DynamicServingCertificateController"1205machine # [ 27.255812] k3s[842]: I1006 09:19:59.069830 842 volume_manager.go:310] "Starting Kubelet Volume Manager"1206machine # [ 27.257325] k3s[842]: E1006 09:19:59.070162 842 kubelet_node_status.go:396] "Error getting the current node from lister" err="node \"machine\" not found"1207machine # [ 27.259354] k3s[842]: E1006 09:19:59.070849 842 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1208machine # [ 27.261578] k3s[842]: I1006 09:19:59.071816 842 desired_state_of_world_populator.go:146] "Desired state populator starts to run"1209machine # [ 27.263163] k3s[842]: I1006 09:19:59.080770 842 factory.go:222] Registration of the systemd container factory successfully1210machine # [ 27.264809] k3s[842]: I1006 09:19:59.080900 842 factory.go:220] Registration of the crio container factory failed: Get "http://%2Fvar%2Frun%2Fcrio%2Fcrio.sock/info": dial unix /var/run/crio/crio.sock: connect: no such file or directory1211machine # [ 27.267578] k3s[842]: I1006 09:19:59.081658 842 reconciler.go:29] "Reconciler: start to sync state"1212machine # [ 27.296270] k3s[842]: E1006 09:19:59.121955 842 kubelet.go:1725] "Image garbage collection failed once. Stats initialization may not have completed yet" err="invalid capacity 0 on image filesystem"1213machine # [ 27.298716] k3s[842]: I1006 09:19:59.122489 842 shared_informer.go:402] "Waiting for caches to sync"1214machine # [ 27.305884] k3s[842]: I1006 09:19:59.130482 842 controller.go:667] quota admission added evaluator for: serviceaccounts1215machine # [ 27.307807] k3s[842]: I1006 09:19:59.133714 842 factory.go:222] Registration of the containerd container factory successfully1216machine # [ 27.315337] k3s[842]: I1006 09:19:59.141201 842 kubelet_network_linux.go:53] "Initialized iptables rules." protocol="IPv6"1217machine # [ 27.354455] k3s[842]: E1006 09:19:59.180308 842 kubelet_node_status.go:396] "Error getting the current node from lister" err="node \"machine\" not found"1218machine # [ 27.356512] k3s[842]: E1006 09:19:59.180390 842 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1219machine # [ 27.421162] k3s[842]: E1006 09:19:59.247020 842 nodelease.go:50] "Failed to get node when trying to set owner ref to the node lease" err="nodes \"machine\" not found" node="machine"1220machine # [ 27.423402] k3s[842]: I1006 09:19:59.248964 842 cpu_manager.go:235] "Starting" policy="none"1221machine # [ 27.424911] k3s[842]: I1006 09:19:59.248981 842 cpu_manager.go:236] "Reconciling" reconcilePeriod="10s"1222machine # [ 27.426247] k3s[842]: I1006 09:19:59.249013 842 state_mem.go:45] "Initialized" logger="CPUManager state checkpoint.CPUManager state memory"1223machine # [ 27.428524] k3s[842]: I1006 09:19:59.249936 842 kubelet_network_linux.go:53] "Initialized iptables rules." protocol="IPv4"1224machine # [ 27.430967] k3s[842]: I1006 09:19:59.250022 842 status_manager.go:277] "Starting to sync pod status with apiserver"1225machine # [ 27.432768] k3s[842]: I1006 09:19:59.250065 842 kubelet.go:2622] "Starting kubelet main sync loop"1226machine # [ 27.434132] k3s[842]: E1006 09:19:59.250116 842 kubelet.go:2646] "Skipping pod synchronization" err="[container runtime status check may not have completed yet, PLEG is not healthy: pleg has yet to be successful]"1227machine # [ 27.436961] k3s[842]: I1006 09:19:59.253955 842 policy_none.go:50] "Start"1228machine # [ 27.438034] k3s[842]: I1006 09:19:59.254025 842 memory_manager.go:190] "Starting memorymanager" policy="None"1229machine # [ 27.444612] k3s[842]: I1006 09:19:59.254046 842 state_mem.go:40] "Initializing new in-memory state store" logger="Memory Manager state checkpoint"1230machine # [ 27.446957] k3s[842]: I1006 09:19:59.255754 842 policy_none.go:44] "Start"1231machine # [ 27.447940] systemd[1]: Created slice libcontainer container kubepods.slice.1232machine # [ 27.457806] k3s[842]: E1006 09:19:59.283703 842 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1233machine # [ 27.467541] k3s[842]: E1006 09:19:59.283958 842 kubelet_node_status.go:396] "Error getting the current node from lister" err="node \"machine\" not found"1234machine # [ 27.476799] k3s[842]: I1006 09:19:59.289329 842 shared_informer.go:409] "Caches are synced"1235machine # [ 27.481022] k3s[842]: I1006 09:19:59.289411 842 shared_informer.go:409] "Caches are synced"1236machine # [ 27.482215] k3s[842]: I1006 09:19:59.289611 842 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1237machine # [ 27.505475] k3s[842]: I1006 09:19:59.329239 842 shared_informer.go:409] "Caches are synced"1238machine # [ 27.515408] systemd[1]: Created slice libcontainer container kubepods-besteffort.slice.1239machine # [ 27.544438] k3s[842]: E1006 09:19:59.370344 842 kubelet.go:2646] "Skipping pod synchronization" err="container runtime status check may not have completed yet"1240machine # [ 27.546534] k3s[842]: I1006 09:19:59.370935 842 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1241machine # [ 27.548234] k3s[842]: E1006 09:19:59.374155 842 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1242machine # [ 27.564076] k3s[842]: I1006 09:19:59.389586 842 shared_informer.go:409] "Caches are synced"1243machine # [ 27.568199] systemd[1]: Created slice libcontainer container kubepods-burstable.slice.1244machine # [ 27.573276] k3s[842]: E1006 09:19:59.399156 842 manager.go:525] "Failed to read data from checkpoint" err="checkpoint is not found" checkpoint="kubelet_internal_checkpoint"1245machine # [ 27.579345] k3s[842]: I1006 09:19:59.401729 842 eviction_manager.go:194] "Eviction manager: starting control loop"1246machine # [ 27.583386] k3s[842]: I1006 09:19:59.401755 842 container_log_manager.go:146] "Initializing container log rotate workers" workers=1 monitorPeriod="10s"1247machine # [ 27.587278] k3s[842]: I1006 09:19:59.407586 842 plugin_manager.go:121] "Starting Kubelet Plugin Manager"1248machine # [ 27.590892] k3s[842]: E1006 09:19:59.416475 842 eviction_manager.go:272] "eviction manager: failed to check if we have separate container filesystem. Ignoring." err="no imagefs label for configured runtime"1249machine # [ 27.597198] k3s[842]: E1006 09:19:59.416531 842 eviction_manager.go:297] "Eviction manager: failed to get summary stats" err="failed to get node info: node \"machine\" not found"1250machine # [ 27.623580] k3s[842]: I1006 09:19:59.449452 842 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller" requiredFeatureGates=["ClusterTrustBundle"]1251machine # [ 27.626578] k3s[842]: I1006 09:19:59.449506 842 controllermanager.go:641] "Warning: skipping controller" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller"1252machine # [ 27.636569] k3s[842]: I1006 09:19:59.462178 842 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="podcertificaterequest-cleaner-controller" requiredFeatureGates=["PodCertificateRequest"]1253machine # [ 27.639474] k3s[842]: I1006 09:19:59.462214 842 controllermanager.go:641] "Warning: skipping controller" controller="podcertificaterequest-cleaner-controller"1254machine # [ 27.645132] k3s[842]: E1006 09:19:59.471030 842 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1255machine # [ 27.683234] k3s[842]: I1006 09:19:59.509067 842 kubelet_node_status.go:75] "Attempting to register node" node="machine"1256machine # [ 27.690158] k3s[842]: I1006 09:19:59.515821 842 kubelet_node_status.go:78] "Successfully registered node" node="machine"1257machine # [ 27.696177] k3s[842]: E1006 09:19:59.515871 842 kubelet_node_status.go:479] "Error updating node status, will retry" err="error getting node \"machine\": node \"machine\" not found"1258machine # [ 27.698902] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Annotations and labels have been set successfully on node: machine"1259machine # [ 27.700888] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Starting flannel with backend vxlan"1260machine # [ 27.873085] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Done waiting for CRD helmchartconfigs.helm.cattle.io to become available"1261machine # [ 27.877664] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available"1262machine # [ 27.881032] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available"1263machine # [ 27.883644] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-40.1.4+up40.1.0.tgz"1264machine # [ 27.886672] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-40.1.4+up40.1.0.tgz"1265machine # [ 27.889654] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml"1266machine # [ 27.892117] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml"1267machine # [ 27.894565] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml"1268machine # [ 27.897206] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml"1269machine # [ 27.899785] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/runtimes.yaml"1270machine # [ 27.902462] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml"1271machine # [ 27.928405] k3s[842]: I1006 09:19:59.754274 842 kubelet_node_status.go:431] "Fast updating node status as it just became ready"1272machine # [ 27.937412] k3s[842]: I1006 09:19:59.763243 842 range_allocator.go:113] "No Secondary Service CIDR provided. Skipping filtering out secondary service addresses" logger="node-ipam-controller"1273machine # [ 27.942020] k3s[842]: I1006 09:19:59.763330 842 controllermanager.go:689] "Warning: controller is disabled" controller="service-lb-controller"1274machine # [ 28.067964] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Starting dynamiclistener CN filter node controller with SANs: [127.0.0.1 ::1 localhost machine 10.0.2.15 fec0::87bf:b810:8c62:a860 10.43.0.1 kubernetes kubernetes.default kubernetes.default.svc kubernetes.default.svc.cluster.local]"1275machine # [ 28.080396] k3s[842]: time="2026-10-06T09:19:59Z" level=info msg="Tunnel server egress proxy mode: agent"1276machine # [ 28.114557] k3s[842]: I1006 09:19:59.940161 842 controllermanager.go:641] "Warning: skipping controller" controller="storage-version-migrator-controller"1277machine: (finished: waiting for unit k3s.service, in 29.22 seconds)1278machine: waiting for unit rustfs-setup.service1279machine # [ 28.178169] k3s[842]: I1006 09:20:00.003782 842 apiserver.go:51] "Watching apiserver"1280machine: (finished: waiting for unit rustfs-setup.service, in 0.05 seconds)1281machine: waiting for unit postgresql.service1282machine: (finished: waiting for unit postgresql.service, in 0.04 seconds)1283subtest: chart deploys and becomes ready1284??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1285 File "/nix/store/zfxjk31pd817qjzxi1374rlf30i2qqni-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391286machine: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s1287??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1288 File "/nix/store/zfxjk31pd817qjzxi1374rlf30i2qqni-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391289machine # [ 28.349796] k3s[842]: I1006 09:20:00.174104 842 desired_state_of_world_populator.go:154] "Finished populating initial desired state of world"1290machine # Error from server (NotFound): namespaces "niks3" not found1291machine # [ 28.507313] k3s[842]: I1006 09:20:00.333079 842 server.go:228] "Successfully retrieved NodeIPs" NodeIPs=["10.0.2.15","fec0::87bf:b810:8c62:a860"]1292machine # [ 28.510623] k3s[842]: E1006 09:20:00.336252 842 server.go:265] "Kube-proxy configuration may be incomplete or incorrect" err="nodePortAddresses is unset; NodePort connections will be accepted on all local IPs. Consider using `--nodeport-addresses primary`"1293machine # [ 28.528905] k3s[842]: I1006 09:20:00.354740 842 server.go:274] "kube-proxy running in dual-stack mode" primary ipFamily="IPv4"1294machine # [ 28.530771] k3s[842]: I1006 09:20:00.354834 842 server_linux.go:137] "Using iptables Proxier"1295machine # [ 28.543387] k3s[842]: I1006 09:20:00.369240 842 proxier.go:241] "Setting route_localnet=1 to allow node-ports on localhost; to change this either disable iptables.localhostNodePorts (--iptables-localhost-nodeports) or set nodePortAddresses (--nodeport-addresses) to filter loopback addresses" ipFamily="IPv4"1296machine # [ 28.550728] k3s[842]: I1006 09:20:00.376594 842 server.go:539] "Version info" version="v1.36.4+k3s1"1297machine # [ 28.552454] k3s[842]: I1006 09:20:00.376638 842 server.go:541] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1298machine # [ 28.563913] k3s[842]: I1006 09:20:00.389797 842 config.go:200] "Starting service config controller"1299machine # [ 28.565392] k3s[842]: I1006 09:20:00.389830 842 shared_informer.go:381] "Waiting for caches to sync" controller="service config"1300machine # [ 28.566960] k3s[842]: I1006 09:20:00.389858 842 config.go:106] "Starting endpoint slice config controller"1301machine # [ 28.568424] k3s[842]: I1006 09:20:00.389868 842 shared_informer.go:381] "Waiting for caches to sync" controller="endpoint slice config"1302machine # [ 28.570055] k3s[842]: I1006 09:20:00.389882 842 config.go:403] "Starting serviceCIDR config controller"1303machine # [ 28.571401] k3s[842]: I1006 09:20:00.389894 842 shared_informer.go:381] "Waiting for caches to sync" controller="serviceCIDR config"1304machine # [ 28.573711] k3s[842]: I1006 09:20:00.390691 842 config.go:309] "Starting node config controller"1305machine # [ 28.575218] k3s[842]: I1006 09:20:00.390707 842 shared_informer.go:381] "Waiting for caches to sync" controller="node config"1306machine # [ 28.579716] k3s[842]: I1006 09:20:00.390717 842 shared_informer.go:388] "Caches are synced" controller="node config"1307machine # [ 28.605477] k3s[842]: time="2026-10-06T09:20:00Z" level=info msg="Creating new TLS secret for kube-system/k3s-serving (count: 11): map[listener.cattle.io/cn-10.0.2.15:10.0.2.15 listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-__1-f16284:::1 listener.cattle.io/cn-fec0__87bf_b810_8c62_a860-bd396f:fec0::87bf:b810:8c62:a860 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc:kubernetes.default.svc listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-localhost:localhost listener.cattle.io/cn-machine:machine listener.cattle.io/fingerprint:SHA1=183580988D4007062C343BA220CB0F2239A65041]"1308machine # [ 28.619387] k3s[842]: time="2026-10-06T09:20:00Z" level=info msg="Active TLS secret kube-system/k3s-serving (ver=257) (count 11): map[listener.cattle.io/cn-10.0.2.15:10.0.2.15 listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-__1-f16284:::1 listener.cattle.io/cn-fec0__87bf_b810_8c62_a860-bd396f:fec0::87bf:b810:8c62:a860 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc:kubernetes.default.svc listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-localhost:localhost listener.cattle.io/cn-machine:machine listener.cattle.io/fingerprint:SHA1=183580988D4007062C343BA220CB0F2239A65041]"1309machine # [ 28.664665] k3s[842]: I1006 09:20:00.490385 842 shared_informer.go:388] "Caches are synced" controller="service config"1310machine # [ 28.765000] k3s[842]: I1006 09:20:00.590525 842 shared_informer.go:388] "Caches are synced" controller="serviceCIDR config"1311machine # [ 28.767465] k3s[842]: I1006 09:20:00.590566 842 shared_informer.go:388] "Caches are synced" controller="endpoint slice config"1312machine # [ 29.279132] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller"1313machine # [ 29.284495] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Creating deploy event broadcaster"1314machine # [ 29.292235] k3s[842]: I1006 09:20:01.112676 842 controller.go:667] quota admission added evaluator for: addons.k3s.cattle.io1315machine # [ 29.294727] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Starting /v1, Kind=Node controller"1316machine # [ 29.300351] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Creating helm-controller event broadcaster"1317machine # [ 29.302426] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" object=kube-system/ccm reason=ApplyingManifest type=Normal1318machine # [ 29.312567] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Labels and annotations have been set successfully on node: machine"1319machine # [ 29.331075] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Cluster dns configmap has been set successfully"1320machine # [ 29.372084] k3s[842]: I1006 09:20:01.197260 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpoints"1321machine # [ 29.375506] k3s[842]: I1006 09:20:01.197366 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="leases.coordination.k8s.io"1322machine # [ 29.379383] k3s[842]: I1006 09:20:01.197408 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="serviceaccounts"1323machine # [ 29.383002] k3s[842]: I1006 09:20:01.197450 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="deployments.apps"1324machine # [ 29.386670] k3s[842]: I1006 09:20:01.197482 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="jobs.batch"1325machine # [ 29.390145] k3s[842]: I1006 09:20:01.197518 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="ingresses.networking.k8s.io"1326machine # [ 29.393929] k3s[842]: I1006 09:20:01.197560 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="replicasets.apps"1327machine # [ 29.397352] k3s[842]: I1006 09:20:01.197586 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="statefulsets.apps"1328machine # [ 29.400554] k3s[842]: I1006 09:20:01.197618 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="poddisruptionbudgets.policy"1329machine # [ 29.403781] k3s[842]: I1006 09:20:01.197660 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="csistoragecapacities.storage.k8s.io"1330machine # [ 29.407179] k3s[842]: I1006 09:20:01.197714 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="addons.k3s.cattle.io"1331machine # [ 29.410260] k3s[842]: I1006 09:20:01.197754 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="daemonsets.apps"1332machine # [ 29.413110] k3s[842]: I1006 09:20:01.197780 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="controllerrevisions.apps"1333machine # [ 29.415852] k3s[842]: I1006 09:20:01.197845 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="cronjobs.batch"1334machine # [ 29.418644] k3s[842]: I1006 09:20:01.197878 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="roles.rbac.authorization.k8s.io"1335machine # [ 29.421445] k3s[842]: I1006 09:20:01.197927 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="limitranges"1336machine # [ 29.423871] k3s[842]: I1006 09:20:01.198013 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="rolebindings.rbac.authorization.k8s.io"1337machine # [ 29.426813] k3s[842]: I1006 09:20:01.198042 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="resourceclaimtemplates.resource.k8s.io"1338machine # [ 29.429650] k3s[842]: I1006 09:20:01.198089 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmchartconfigs.helm.cattle.io"1339machine # [ 29.432266] k3s[842]: I1006 09:20:01.198136 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="horizontalpodautoscalers.autoscaling"1340machine # [ 29.434913] k3s[842]: I1006 09:20:01.198171 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="networkpolicies.networking.k8s.io"1341machine # [ 29.437482] k3s[842]: I1006 09:20:01.198195 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpointslices.discovery.k8s.io"1342machine # [ 29.439925] k3s[842]: I1006 09:20:01.198276 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="podtemplates"1343machine # [ 29.442267] k3s[842]: I1006 09:20:01.198307 842 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmcharts.helm.cattle.io"1344machine # [ 29.444607] k3s[842]: I1006 09:20:01.198350 842 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="podgroup-protection-controller" requiredFeatureGates=["GenericWorkload"]1345machine # [ 29.446934] k3s[842]: I1006 09:20:01.198372 842 controllermanager.go:641] "Warning: skipping controller" controller="podgroup-protection-controller"1346machine # [ 29.448748] k3s[842]: I1006 09:20:01.198383 842 controllermanager.go:689] "Warning: controller is disabled" controller="bootstrap-signer-controller"1347machine # [ 29.670121] k3s[842]: I1006 09:20:01.495923 842 controllermanager.go:689] "Warning: controller is disabled" controller="selinux-warning-controller"1348machine # [ 29.679336] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" object=kube-system/ccm reason=AppliedManifest type=Normal1349machine # [ 29.698411] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/ci.yaml\"" object=kube-system/ci reason=ApplyingManifest type=Normal1350machine # Error from server (NotFound): namespaces "niks3" not found1351machine # [ 30.123873] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Deferred node password secret validation complete" object=machine reason=NodePasswordValidationComplete type=Normal1352machine # [ 30.129729] k3s[842]: I1006 09:20:01.955598 842 controllermanager.go:689] "Warning: controller is disabled" controller="node-route-controller"1353machine # [ 30.134720] k3s[842]: I1006 09:20:01.957698 842 controllermanager.go:689] "Warning: controller is disabled" controller="cloud-node-lifecycle-controller"1354machine # [ 30.136766] k3s[842]: I1006 09:20:01.957743 842 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="storageversion-garbage-collector-controller" requiredFeatureGates=["APIServerIdentity","StorageVersionAPI"]1355machine # [ 30.139687] k3s[842]: I1006 09:20:01.957768 842 controllermanager.go:641] "Warning: skipping controller" controller="storageversion-garbage-collector-controller"1356machine # [ 30.156045] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ci.yaml\"" object=kube-system/ci reason=AppliedManifest type=Normal1357machine # [ 30.176051] k3s[842]: time="2026-10-06T09:20:01Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/coredns.yaml\"" object=kube-system/coredns reason=ApplyingManifest type=Normal1358machine # [ 30.290879] k3s[842]: I1006 09:20:02.116692 842 serving.go:417] Generated self-signed cert in-memory1359machine # [ 30.425564] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Starting rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding controller"1360machine # [ 30.444099] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Starting batch/v1, Kind=Job controller"1361machine # [ 30.446311] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Starting /v1, Kind=Secret controller"1362machine # [ 30.452246] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Starting /v1, Kind=ConfigMap controller"1363machine # [ 30.454353] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Starting /v1, Kind=ServiceAccount controller"1364machine # [ 30.497887] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller"1365machine # [ 30.499652] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller"1366machine # [ 30.503125] k3s[842]: I1006 09:20:02.329027 842 node_lifecycle_controller.go:402] "Controller will reconcile labels" logger="node-lifecycle-controller"1367machine # [ 30.580130] k3s[842]: I1006 09:20:02.404639 842 serving.go:417] Generated self-signed cert in-memory1368machine # [ 30.786338] k3s[842]: I1006 09:20:02.612052 842 controller.go:667] quota admission added evaluator for: deployments.apps1369machine # [ 30.935626] k3s[842]: I1006 09:20:02.761434 842 alloc.go:329] "allocated clusterIPs" service="kube-system/kube-dns" clusterIPs={"IPv4":"10.43.0.10"}1370machine # [ 30.961642] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/coredns.yaml\"" object=kube-system/coredns reason=AppliedManifest type=Normal1371machine # [ 30.990610] k3s[842]: I1006 09:20:02.816432 842 controllermanager.go:163] Version: v1.36.4+k3s11372machine # [ 30.998503] k3s[842]: I1006 09:20:02.824406 842 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1373machine # [ 31.000380] k3s[842]: I1006 09:20:02.826300 842 shared_informer.go:402] "Waiting for caches to sync"1374machine # [ 31.002434] k3s[842]: I1006 09:20:02.825064 842 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1375machine # [ 31.007081] k3s[842]: I1006 09:20:02.827691 842 shared_informer.go:402] "Waiting for caches to sync"1376machine # [ 31.009257] k3s[842]: I1006 09:20:02.825077 842 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1377machine # [ 31.012464] k3s[842]: I1006 09:20:02.827724 842 shared_informer.go:402] "Waiting for caches to sync"1378machine # [ 31.013787] k3s[842]: I1006 09:20:02.825039 842 tlsconfig.go:243] "Starting DynamicServingCertificateController"1379machine # [ 31.015268] k3s[842]: I1006 09:20:02.825018 842 secure_serving.go:214] Serving securely on 127.0.0.1:102581380machine # Error from server (NotFound): namespaces "niks3" not found1381machine # [ 31.028126] k3s[842]: time="2026-10-06T09:20:02Z" level=info msg="Creating service-lb-controller event broadcaster"1382machine # [ 31.102530] k3s[842]: I1006 09:20:02.928265 842 shared_informer.go:409] "Caches are synced"1383machine # [ 31.105240] k3s[842]: I1006 09:20:02.928294 842 shared_informer.go:409] "Caches are synced"1384machine # [ 31.107216] k3s[842]: I1006 09:20:02.928323 842 shared_informer.go:409] "Caches are synced"1385machine # [ 31.271081] k3s[842]: I1006 09:20:03.095656 842 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="resourcepoolstatusrequest-controller" requiredFeatureGates=["DRAResourcePoolStatus"]1386machine # [ 31.275548] k3s[842]: I1006 09:20:03.095735 842 controllermanager.go:641] "Warning: skipping controller" controller="resourcepoolstatusrequest-controller"1387machine # [ 31.286935] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Starting /v1, Kind=Node controller"1388machine # [ 31.294620] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Starting /v1, Kind=Pod controller"1389machine # [ 31.301959] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Starting apps/v1, Kind=DaemonSet controller"1390machine # [ 31.310227] k3s[842]: W1006 09:20:03.135197 842 controllermanager.go:315] "node-route-controller" is disabled1391machine # [ 31.316342] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Starting discovery.k8s.io/v1, Kind=EndpointSlice controller"1392machine # [ 31.318831] k3s[842]: I1006 09:20:03.135953 842 controllermanager.go:338] Started "cloud-node-controller"1393machine # [ 31.321444] k3s[842]: I1006 09:20:03.136288 842 controllermanager.go:338] Started "cloud-node-lifecycle-controller"1394machine # [ 31.323957] k3s[842]: I1006 09:20:03.136840 842 controllermanager.go:338] Started "service-lb-controller"1395machine # [ 31.326141] k3s[842]: I1006 09:20:03.137795 842 node_controller.go:179] Sending events to api server.1396machine # [ 31.328171] k3s[842]: I1006 09:20:03.137883 842 node_lifecycle_controller.go:112] Sending events to api server1397machine # [ 31.330301] k3s[842]: I1006 09:20:03.138072 842 node_controller.go:188] Waiting for informer caches to sync1398machine # [ 31.332486] k3s[842]: I1006 09:20:03.138194 842 controller.go:235] Starting service controller1399machine # [ 31.334403] k3s[842]: I1006 09:20:03.138231 842 shared_informer.go:402] "Waiting for caches to sync"1400machine # [ 31.413512] k3s[842]: I1006 09:20:03.238390 842 shared_informer.go:409] "Caches are synced"1401machine # [ 31.415586] k3s[842]: I1006 09:20:03.238550 842 node_controller.go:432] Initializing node machine with cloud provider1402machine # [ 31.433325] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Adding node OwnerReference to node-password secret machine.node-password.k3s"1403machine # [ 31.451209] k3s[842]: E1006 09:20:03.275626 842 options.go:205] The manifest file is empty, ignoring.1404machine # [ 31.453656] k3s[842]: I1006 09:20:03.277716 842 node_controller.go:477] Successfully initialized node machine with cloud provider1405machine # [ 31.456268] k3s[842]: I1006 09:20:03.277918 842 event.go:389] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="v1" type="Normal" reason="Synced" message="Node synced successfully"1406machine # [ 31.467283] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Synced coredns NodeHosts entries for machine"1407machine # [ 31.476266] k3s[842]: I1006 09:20:03.296810 842 server.go:176] "Starting Kubernetes Scheduler" version="v1.36.4+k3s1"1408machine # [ 31.478223] k3s[842]: I1006 09:20:03.296860 842 server.go:178] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1409machine # [ 31.485904] k3s[842]: I1006 09:20:03.302747 842 secure_serving.go:214] Serving securely on 127.0.0.1:102591410machine # [ 31.487612] k3s[842]: I1006 09:20:03.302883 842 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1411machine # [ 31.492212] k3s[842]: I1006 09:20:03.302903 842 shared_informer.go:402] "Waiting for caches to sync"1412machine # [ 31.496342] k3s[842]: I1006 09:20:03.302943 842 dynamic_serving_content.go:135] "Starting controller" name="serving-cert::/var/lib/rancher/k3s/server/tls/kube-scheduler/kube-scheduler.crt::/var/lib/rancher/k3s/server/tls/kube-scheduler/kube-scheduler.key"1413machine # [ 31.499633] k3s[842]: I1006 09:20:03.303096 842 tlsconfig.go:243] "Starting DynamicServingCertificateController"1414machine # [ 31.503859] k3s[842]: I1006 09:20:03.305346 842 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1415machine # [ 31.506748] k3s[842]: I1006 09:20:03.305371 842 shared_informer.go:402] "Waiting for caches to sync"1416machine # [ 31.508239] k3s[842]: I1006 09:20:03.305390 842 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1417machine # [ 31.512177] k3s[842]: I1006 09:20:03.305428 842 shared_informer.go:402] "Waiting for caches to sync"1418machine # [ 31.572193] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Deleting manifest at \"/var/lib/rancher/k3s/server/manifests/local-storage.yaml\"" object=kube-system/local-storage reason=DeletingManifest type=Normal1419machine # [ 31.581598] k3s[842]: I1006 09:20:03.403595 842 shared_informer.go:409] "Caches are synced"1420machine # [ 31.583531] k3s[842]: I1006 09:20:03.405440 842 shared_informer.go:409] "Caches are synced"1421machine # [ 31.585245] k3s[842]: I1006 09:20:03.405480 842 shared_informer.go:409] "Caches are synced"1422machine # [ 31.589945] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/niks3.yaml\"" object=kube-system/niks3 reason=ApplyingManifest type=Normal1423machine # [ 31.721951] k3s[842]: I1006 09:20:03.547629 842 controller.go:667] quota admission added evaluator for: helmcharts.helm.cattle.io1424machine # [ 31.728474] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/niks3.yaml\"" object=kube-system/niks3 reason=AppliedManifest type=Normal1425machine # [ 31.751963] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/rolebindings.yaml\"" object=kube-system/rolebindings reason=ApplyingManifest type=Normal1426machine # [ 31.973471] k3s[842]: time="2026-10-06T09:20:03Z" level=info msg="Event occurred" apiVersion=helm.cattle.io/v1 fieldPath= kind=HelmChart logger=k3s/helm-controller message="Applying HelmChart from https://%{KUBERNETES_API}%/static/charts/niks3.tgz using Job kube-system/helm-install-niks3 " object=kube-system/niks3 reason=ApplyJob type=Normal1427machine # [ 31.988503] k3s[842]: I1006 09:20:03.809902 842 daemon_controller.go:364] "Starting daemon sets controller"1428machine # [ 31.990760] k3s[842]: I1006 09:20:03.809947 842 shared_informer.go:402] "Waiting for caches to sync"1429machine # [ 31.992822] k3s[842]: I1006 09:20:03.810519 842 shared_informer.go:402] "Waiting for caches to sync"1430machine # [ 32.000258] k3s[842]: I1006 09:20:03.810586 842 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-legacy-unknown"1431machine # [ 32.003131] k3s[842]: I1006 09:20:03.810603 842 shared_informer.go:402] "Waiting for caches to sync"1432machine # [ 32.005150] k3s[842]: I1006 09:20:03.810670 842 pv_controller_base.go:318] "Starting persistent volume controller"1433machine # [ 32.007354] k3s[842]: I1006 09:20:03.810685 842 shared_informer.go:402] "Waiting for caches to sync"1434machine # [ 32.012225] k3s[842]: I1006 09:20:03.810781 842 clusterroleaggregation_controller.go:176] "Starting ClusterRoleAggregator controller"1435machine # [ 32.014507] k3s[842]: I1006 09:20:03.810801 842 shared_informer.go:402] "Waiting for caches to sync"1436machine # [ 32.019420] k3s[842]: I1006 09:20:03.810848 842 gc_controller.go:98] "Starting GC controller"1437machine # [ 32.021078] k3s[842]: I1006 09:20:03.810862 842 shared_informer.go:402] "Waiting for caches to sync"1438machine # [ 32.022715] k3s[842]: I1006 09:20:03.810941 842 job_controller.go:336] "Starting job controller"1439machine # [ 32.028179] k3s[842]: I1006 09:20:03.810964 842 shared_informer.go:402] "Waiting for caches to sync"1440machine # [ 32.029756] k3s[842]: I1006 09:20:03.810991 842 certificate_controller.go:120] "Starting certificate controller" name="csrapproving"1441machine # [ 32.031684] k3s[842]: I1006 09:20:03.811006 842 shared_informer.go:402] "Waiting for caches to sync"1442machine # [ 32.033252] k3s[842]: I1006 09:20:03.811042 842 cleaner.go:83] "Starting CSR cleaner controller"1443machine # [ 32.035605] k3s[842]: I1006 09:20:03.811113 842 ttlafterfinished_controller.go:112] "Starting TTL after finished controller"1444machine # [ 32.040141] k3s[842]: I1006 09:20:03.811129 842 shared_informer.go:402] "Waiting for caches to sync"1445machine # [ 32.041601] k3s[842]: I1006 09:20:03.811152 842 publisher.go:107] "Starting root CA cert publisher controller"1446machine # [ 32.043168] k3s[842]: I1006 09:20:03.811167 842 shared_informer.go:402] "Waiting for caches to sync"1447machine # [ 32.047599] k3s[842]: I1006 09:20:03.811204 842 legacy_serviceaccount_token_cleaner.go:103] "Starting legacy service account token cleaner controller"1448machine # [ 32.049854] k3s[842]: I1006 09:20:03.811220 842 shared_informer.go:402] "Waiting for caches to sync"1449machine # [ 32.052771] k3s[842]: I1006 09:20:03.811287 842 endpointslice_controller.go:280] "Starting endpoint slice controller"1450machine # [ 32.054311] k3s[842]: I1006 09:20:03.811307 842 shared_informer.go:402] "Waiting for caches to sync"1451machine # [ 32.060194] k3s[842]: I1006 09:20:03.811335 842 ttl_controller.go:127] "Starting TTL controller"1452machine # [ 32.061472] k3s[842]: I1006 09:20:03.811353 842 shared_informer.go:402] "Waiting for caches to sync"1453machine # [ 32.062752] k3s[842]: I1006 09:20:03.811480 842 node_ipam_controller.go:142] "Starting ipam controller"1454machine # [ 32.064064] k3s[842]: I1006 09:20:03.811502 842 shared_informer.go:402] "Waiting for caches to sync"1455machine # [ 32.065314] k3s[842]: I1006 09:20:03.811538 842 controller.go:174] "Starting ephemeral volume controller"1456machine # [ 32.072172] k3s[842]: I1006 09:20:03.811557 842 shared_informer.go:402] "Waiting for caches to sync"1457machine # [ 32.073557] k3s[842]: I1006 09:20:03.811586 842 shared_informer.go:402] "Waiting for caches to sync"1458machine # [ 32.074898] k3s[842]: I1006 09:20:03.811658 842 replica_set.go:285] "Starting controller" name="replicationcontroller"1459machine # [ 32.076531] k3s[842]: I1006 09:20:03.811677 842 shared_informer.go:402] "Waiting for caches to sync"1460machine # [ 32.077893] k3s[842]: I1006 09:20:03.811734 842 deployment_controller.go:180] "Starting controller" controller="deployment"1461machine # [ 32.079423] k3s[842]: I1006 09:20:03.811751 842 shared_informer.go:402] "Waiting for caches to sync"1462machine # [ 32.080751] k3s[842]: I1006 09:20:03.811806 842 replica_set.go:285] "Starting controller" name="replicaset"1463machine # [ 32.082072] k3s[842]: I1006 09:20:03.811843 842 shared_informer.go:402] "Waiting for caches to sync"1464machine # [ 32.083344] k3s[842]: I1006 09:20:03.811909 842 stateful_set.go:234] "Starting stateful set controller"1465machine # [ 32.088221] k3s[842]: I1006 09:20:03.811929 842 shared_informer.go:402] "Waiting for caches to sync"1466machine # [ 32.089546] k3s[842]: I1006 09:20:03.811956 842 expand_controller.go:328] "Starting expand controller"1467machine # [ 32.090814] k3s[842]: I1006 09:20:03.811970 842 shared_informer.go:402] "Waiting for caches to sync"1468machine # [ 32.094894] k3s[842]: I1006 09:20:03.812052 842 controller.go:753] "Starting resource claim controller"1469machine # [ 32.096298] k3s[842]: I1006 09:20:03.812068 842 shared_informer.go:402] "Waiting for caches to sync"1470machine # [ 32.097549] k3s[842]: I1006 09:20:03.812093 842 taint_eviction.go:283] "Starting" controller="taint-eviction-controller"1471machine # [ 32.099041] k3s[842]: I1006 09:20:03.812149 842 taint_eviction.go:288] "Sending events to API server"1472machine # [ 32.104128] k3s[842]: I1006 09:20:03.812164 842 shared_informer.go:402] "Waiting for caches to sync"1473machine # [ 32.105425] k3s[842]: I1006 09:20:03.812491 842 tokencleaner.go:117] "Starting token cleaner controller"1474machine # [ 32.106761] k3s[842]: I1006 09:20:03.812531 842 shared_informer.go:402] "Waiting for caches to sync"1475machine # [ 32.110397] k3s[842]: I1006 09:20:03.812564 842 pvc_protection_controller.go:172] "Starting PVC protection controller"1476machine # [ 32.111915] k3s[842]: I1006 09:20:03.812577 842 shared_informer.go:402] "Waiting for caches to sync"1477machine # [ 32.113317] k3s[842]: I1006 09:20:03.812839 842 endpoints_controller.go:193] "Starting endpoint controller"1478machine # [ 32.114664] k3s[842]: I1006 09:20:03.812862 842 shared_informer.go:402] "Waiting for caches to sync"1479machine # [ 32.115919] k3s[842]: I1006 09:20:03.812910 842 horizontal.go:204] "Starting HPA controller"1480machine # [ 32.120123] k3s[842]: I1006 09:20:03.812925 842 shared_informer.go:402] "Waiting for caches to sync"1481machine # [ 32.121439] k3s[842]: I1006 09:20:03.812985 842 node_lifecycle_controller.go:436] "Sending events to api server"1482machine # [ 32.122887] k3s[842]: I1006 09:20:03.813021 842 node_lifecycle_controller.go:443] "Starting node controller"1483machine # [ 32.127372] k3s[842]: I1006 09:20:03.813032 842 shared_informer.go:402] "Waiting for caches to sync"1484machine # [ 32.132133] k3s[842]: I1006 09:20:03.813065 842 vac_protection_controller.go:206] "Starting VAC protection controller"1485machine # [ 32.133629] k3s[842]: I1006 09:20:03.813079 842 shared_informer.go:402] "Waiting for caches to sync"1486machine # [ 32.134893] k3s[842]: I1006 09:20:03.813134 842 servicecidrs_controller.go:137] "Starting" controller="service-cidr-controller"1487machine # [ 32.136488] k3s[842]: I1006 09:20:03.813154 842 shared_informer.go:402] "Waiting for caches to sync"1488machine # [ 32.137869] k3s[842]: I1006 09:20:03.813179 842 serviceaccounts_controller.go:117] "Starting service account controller"1489machine # [ 32.144239] k3s[842]: I1006 09:20:03.813194 842 shared_informer.go:402] "Waiting for caches to sync"1490machine # [ 32.145587] k3s[842]: I1006 09:20:03.813221 842 disruption.go:453] "Sending events to api server."1491machine # [ 32.146858] k3s[842]: I1006 09:20:03.813256 842 disruption.go:460] "Starting disruption controller"1492machine # [ 32.148115] k3s[842]: I1006 09:20:03.813267 842 shared_informer.go:402] "Waiting for caches to sync"1493machine # [ 32.149355] k3s[842]: I1006 09:20:03.813290 842 pv_protection_controller.go:81] "Starting PV protection controller"1494machine # [ 32.152285] k3s[842]: I1006 09:20:03.813304 842 shared_informer.go:402] "Waiting for caches to sync"1495machine # [ 32.154355] k3s[842]: I1006 09:20:03.813349 842 device_taint_eviction.go:783] "Starting" controller="device-taint-eviction-controller" numWorkers=81496machine # [ 32.160137] k3s[842]: I1006 09:20:03.813567 842 endpointslicemirroring_controller.go:226] "Starting EndpointSliceMirroring controller"1497machine # [ 32.161908] k3s[842]: I1006 09:20:03.813587 842 shared_informer.go:402] "Waiting for caches to sync"1498machine # [ 32.163227] k3s[842]: I1006 09:20:03.813620 842 namespace_controller.go:202] "Starting namespace controller"1499machine # [ 32.164621] k3s[842]: I1006 09:20:03.813637 842 shared_informer.go:402] "Waiting for caches to sync"1500machine # [ 32.165876] k3s[842]: I1006 09:20:03.813916 842 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-serving"1501machine # [ 32.167618] k3s[842]: I1006 09:20:03.813937 842 shared_informer.go:402] "Waiting for caches to sync"1502machine # [ 32.172150] k3s[842]: I1006 09:20:03.813959 842 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-client"1503machine # [ 32.173965] k3s[842]: I1006 09:20:03.814029 842 shared_informer.go:402] "Waiting for caches to sync"1504machine # [ 32.175225] k3s[842]: I1006 09:20:03.814097 842 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kube-apiserver-client"1505machine # [ 32.180160] k3s[842]: I1006 09:20:03.814111 842 shared_informer.go:402] "Waiting for caches to sync"1506machine # [ 32.181471] k3s[842]: I1006 09:20:03.814148 842 dynamic_serving_content.go:135] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/server-ca.key"1507machine # [ 32.188125] k3s[842]: I1006 09:20:03.814418 842 attach_detach_controller.go:334] "Starting attach detach controller"1508machine # [ 32.189690] k3s[842]: I1006 09:20:03.814442 842 shared_informer.go:402] "Waiting for caches to sync"1509machine # [ 32.190962] k3s[842]: I1006 09:20:03.814618 842 resource_quota_controller.go:297] "Starting resource quota controller"1510machine # [ 32.196149] k3s[842]: I1006 09:20:03.814639 842 shared_informer.go:402] "Waiting for caches to sync"1511machine # [ 32.197476] k3s[842]: I1006 09:20:03.814737 842 garbagecollector.go:141] "Starting controller" controller="garbagecollector"1512machine # [ 32.199173] k3s[842]: I1006 09:20:03.814764 842 shared_informer.go:402] "Waiting for caches to sync"1513machine # [ 32.200467] k3s[842]: I1006 09:20:03.814812 842 cronjob_controllerv2.go:143] "Starting cronjob controller v2"1514machine # [ 32.201824] k3s[842]: I1006 09:20:03.814829 842 shared_informer.go:402] "Waiting for caches to sync"1515machine # [ 32.208145] k3s[842]: I1006 09:20:03.814891 842 device_taint_eviction.go:823] "Sending events to api server"1516machine # [ 32.209564] k3s[842]: I1006 09:20:03.815031 842 device_taint_eviction.go:1023] "Waiting" for="cache and event handler sync"1517machine # [ 32.211120] k3s[842]: I1006 09:20:03.815084 842 dynamic_serving_content.go:135] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/server-ca.key"1518machine # [ 32.213839] k3s[842]: I1006 09:20:03.815223 842 dynamic_serving_content.go:135] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/client-ca.key"1519machine # [ 32.217860] k3s[842]: I1006 09:20:03.815332 842 dynamic_serving_content.go:135] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/client-ca.key"1520machine # [ 32.224301] k3s[842]: I1006 09:20:03.815821 842 resource_quota_monitor.go:309] "QuotaMonitor running"1521machine # [ 32.225596] k3s[842]: I1006 09:20:03.816051 842 graph_builder.go:387] "Running" component="GraphBuilder"1522machine # [ 32.227024] k3s[842]: I1006 09:20:03.857223 842 shared_informer.go:402] "Waiting for caches to sync"1523machine # [ 32.232159] k3s[842]: I1006 09:20:03.899922 842 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.ResourceSlice + event handler k8s.io/kubernetes/pkg/controller/devicetainteviction.(*Controller).Run"1524machine # [ 32.235343] k3s[842]: I1006 09:20:03.900020 842 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.ResourceSlice"1525machine # [ 32.237592] k3s[842]: I1006 09:20:03.916379 842 shared_informer.go:409] "Caches are synced"1526machine # [ 32.244168] k3s[842]: I1006 09:20:03.916491 842 shared_informer.go:409] "Caches are synced"1527machine # [ 32.245465] k3s[842]: I1006 09:20:03.916610 842 shared_informer.go:409] "Caches are synced"1528machine # [ 32.246652] k3s[842]: I1006 09:20:03.916676 842 shared_informer.go:409] "Caches are synced"1529machine # [ 32.247809] k3s[842]: I1006 09:20:03.918741 842 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.ResourceClaim"1530machine # [ 32.250043] k3s[842]: I1006 09:20:03.918776 842 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.ResourceClaim + event handler k8s.io/kubernetes/pkg/controller/devicetainteviction.(*Controller).Run"1531machine # [ 32.253182] k3s[842]: I1006 09:20:03.937909 842 shared_informer.go:402] "Waiting for caches to sync"1532machine # [ 32.254544] k3s[842]: I1006 09:20:04.013298 842 shared_informer.go:409] "Caches are synced"1533machine # [ 32.255698] k3s[842]: I1006 09:20:04.013334 842 shared_informer.go:409] "Caches are synced"1534machine # [ 32.260254] k3s[842]: I1006 09:20:04.013804 842 shared_informer.go:409] "Caches are synced"1535machine # [ 32.261437] k3s[842]: I1006 09:20:04.020205 842 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.DeviceClass"1536machine # [ 32.263524] k3s[842]: I1006 09:20:04.021721 842 actual_state_of_world.go:541] "Failed to update statusUpdateNeeded field in actual state of world" logger="persistentvolume-attach-detach-controller" err="Failed to set statusUpdateNeeded to needed true, because nodeName=\"machine\" does not exist"1537machine # [ 32.272149] k3s[842]: I1006 09:20:04.026476 842 shared_informer.go:409] "Caches are synced"1538machine # [ 32.273403] k3s[842]: I1006 09:20:04.026523 842 shared_informer.go:409] "Caches are synced"1539machine # [ 32.274619] k3s[842]: I1006 09:20:04.026684 842 shared_informer.go:409] "Caches are synced"1540machine # [ 32.275767] k3s[842]: I1006 09:20:04.026707 842 shared_informer.go:409] "Caches are synced"1541machine # [ 32.280180] k3s[842]: I1006 09:20:04.029202 842 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.Pod"1542machine # [ 32.282211] k3s[842]: I1006 09:20:04.029246 842 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.Pod + event handler k8s.io/kubernetes/pkg/controller/devicetainteviction.(*Controller).Run"1543machine # [ 32.287448] k3s[842]: I1006 09:20:04.062815 842 controller.go:667] quota admission added evaluator for: jobs.batch1544machine # [ 32.289004] k3s[842]: I1006 09:20:04.062957 842 shared_informer.go:409] "Caches are synced"1545machine # [ 32.290202] k3s[842]: I1006 09:20:04.110968 842 shared_informer.go:409] "Caches are synced"1546machine # [ 32.291444] k3s[842]: I1006 09:20:04.111016 842 shared_informer.go:409] "Caches are synced"1547machine # [ 32.296227] k3s[842]: I1006 09:20:04.111053 842 shared_informer.go:409] "Caches are synced"1548machine # [ 32.297467] k3s[842]: I1006 09:20:04.111150 842 shared_informer.go:409] "Caches are synced"1549machine # [ 32.298694] k3s[842]: I1006 09:20:04.113152 842 shared_informer.go:409] "Caches are synced"1550machine # [ 32.299851] k3s[842]: I1006 09:20:04.113189 842 shared_informer.go:409] "Caches are synced"1551machine # [ 32.302837] k3s[842]: I1006 09:20:04.113463 842 shared_informer.go:409] "Caches are synced"1552machine # [ 32.304120] k3s[842]: I1006 09:20:04.114036 842 shared_informer.go:409] "Caches are synced"1553machine # [ 32.305274] k3s[842]: I1006 09:20:04.114076 842 shared_informer.go:409] "Caches are synced"1554machine # [ 32.306441] k3s[842]: I1006 09:20:04.114104 842 shared_informer.go:409] "Caches are synced"1555machine # [ 32.307669] k3s[842]: I1006 09:20:04.114147 842 shared_informer.go:409] "Caches are synced"1556machine # [ 32.312131] k3s[842]: I1006 09:20:04.114296 842 shared_informer.go:409] "Caches are synced"1557machine # [ 32.313445] k3s[842]: I1006 09:20:04.115786 842 shared_informer.go:409] "Caches are synced"1558machine # [ 32.314703] k3s[842]: I1006 09:20:04.115975 842 shared_informer.go:409] "Caches are synced"1559machine # [ 32.315855] k3s[842]: I1006 09:20:04.116057 842 shared_informer.go:409] "Caches are synced"1560machine # [ 32.320190] k3s[842]: I1006 09:20:04.116124 842 shared_informer.go:409] "Caches are synced"1561machine # [ 32.321485] k3s[842]: I1006 09:20:04.116777 842 shared_informer.go:409] "Caches are synced"1562machine # [ 32.322661] k3s[842]: I1006 09:20:04.116838 842 range_allocator.go:177] "Sending events to api server"1563machine # [ 32.323924] k3s[842]: I1006 09:20:04.116872 842 range_allocator.go:181] "Starting range CIDR allocator"1564machine # [ 32.328201] k3s[842]: I1006 09:20:04.116880 842 shared_informer.go:402] "Waiting for caches to sync"1565machine # [ 32.332072] k3s[842]: I1006 09:20:04.116887 842 shared_informer.go:409] "Caches are synced"1566machine # [ 32.333292] k3s[842]: I1006 09:20:04.117295 842 shared_informer.go:409] "Caches are synced"1567machine # [ 32.334452] k3s[842]: I1006 09:20:04.117331 842 shared_informer.go:409] "Caches are synced"1568machine # [ 32.335615] k3s[842]: I1006 09:20:04.117356 842 shared_informer.go:409] "Caches are synced"1569machine # [ 32.339657] k3s[842]: I1006 09:20:04.117924 842 shared_informer.go:409] "Caches are synced"1570machine # [ 32.340926] k3s[842]: I1006 09:20:04.117956 842 shared_informer.go:409] "Caches are synced"1571machine # [ 32.342066] k3s[842]: I1006 09:20:04.123426 842 shared_informer.go:409] "Caches are synced"1572machine # Error from server (NotFound): namespaces "niks3" not found1573machine # [ 32.343221] k3s[842]: I1006 09:20:04.129060 842 shared_informer.go:409] "Caches are synced"1574machine # [ 32.348119] k3s[842]: I1006 09:20:04.129182 842 shared_informer.go:409] "Caches are synced"1575machine # [ 32.349344] k3s[842]: I1006 09:20:04.129245 842 shared_informer.go:409] "Caches are synced"1576machine # [ 32.350491] k3s[842]: I1006 09:20:04.129330 842 shared_informer.go:409] "Caches are synced"1577machine # [ 32.351655] k3s[842]: I1006 09:20:04.129826 842 shared_informer.go:409] "Caches are synced"1578machine # [ 32.355321] k3s[842]: I1006 09:20:04.129920 842 node_lifecycle_controller.go:1217] "Initializing eviction metric for zone" zone=""1579machine # [ 32.357150] k3s[842]: I1006 09:20:04.134101 842 node_lifecycle_controller.go:869] "Missing timestamp for Node. Assuming now as a timestamp" node="machine"1580machine # [ 32.364258] k3s[842]: I1006 09:20:04.134193 842 node_lifecycle_controller.go:1063] "Controller detected that zone is now in new state" zone="" newState="Normal"1581machine # [ 32.366193] k3s[842]: I1006 09:20:04.135324 842 shared_informer.go:409] "Caches are synced"1582machine # [ 32.367374] k3s[842]: I1006 09:20:04.136148 842 shared_informer.go:409] "Caches are synced"1583machine # [ 32.369652] k3s[842]: I1006 09:20:04.149022 842 range_allocator.go:433] "Set node PodCIDR" node="machine" podCIDRs=["10.42.0.0/24"]1584machine # [ 32.371595] k3s[842]: time="2026-10-06T09:20:04Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/rolebindings.yaml\"" object=kube-system/rolebindings reason=AppliedManifest type=Normal1585machine # [ 32.380123] k3s[842]: time="2026-10-06T09:20:04Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/runtimes.yaml\"" object=kube-system/runtimes reason=ApplyingManifest type=Normal1586machine # [ 32.536947] k3s[842]: time="2026-10-06T09:20:04Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/runtimes.yaml\"" object=kube-system/runtimes reason=AppliedManifest type=Normal1587machine # [ 32.675992] k3s[842]: time="2026-10-06T09:20:04Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Deleting manifest at \"/var/lib/rancher/k3s/server/manifests/traefik.yaml\"" object=kube-system/traefik reason=DeletingManifest type=Normal1588machine # [ 32.708101] k3s[842]: time="2026-10-06T09:20:04Z" level=info msg="Event occurred" apiVersion=helm.cattle.io/v1 fieldPath= kind=HelmChart logger=k3s/helm-controller message="Resumed synced Job kube-system/helm-install-niks3" object=kube-system/niks3 reason=ResumeJob type=Normal1589machine # [ 32.730906] k3s[842]: I1006 09:20:04.556736 842 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161590machine # [ 32.736984] k3s[842]: I1006 09:20:04.562560 842 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161591machine # [ 32.828772] k3s[842]: time="2026-10-06T09:20:04Z" level=info msg="Flannel found PodCIDR assigned for node machine"1592machine # [ 32.831150] systemd[1]: Created slice libcontainer container kubepods-burstable-pod5e8de259_f3a2_490e_b885_c3ac2433099b.slice.1593machine # [ 32.847611] k3s[842]: time="2026-10-06T09:20:04Z" level=info msg="The interface eth0 with ipv4 address 10.0.2.15 will be used by flannel"1594machine # [ 32.850099] k3s[842]: I1006 09:20:04.674455 842 kube.go:139] Waiting 10m0s for node controller to sync1595machine # [ 32.854085] k3s[842]: I1006 09:20:04.674702 842 kube.go:537] Starting kube subnet manager1596machine # [ 32.870127] k3s[842]: I1006 09:20:04.691094 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-helm\") pod \"helm-install-niks3-hc6hk\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") " pod="kube-system/helm-install-niks3-hc6hk"1597machine # [ 32.876407] k3s[842]: I1006 09:20:04.691162 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-cache\") pod \"helm-install-niks3-hc6hk\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") " pod="kube-system/helm-install-niks3-hc6hk"1598machine # [ 32.882183] k3s[842]: I1006 09:20:04.691186 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-config\") pod \"helm-install-niks3-hc6hk\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") " pod="kube-system/helm-install-niks3-hc6hk"1599machine # [ 32.887753] k3s[842]: I1006 09:20:04.691230 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-tmp\") pod \"helm-install-niks3-hc6hk\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") " pod="kube-system/helm-install-niks3-hc6hk"1600machine # [ 32.892865] k3s[842]: I1006 09:20:04.691257 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"values\" (UniqueName: \"kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-values\") pod \"helm-install-niks3-hc6hk\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") " pod="kube-system/helm-install-niks3-hc6hk"1601machine # [ 32.897720] k3s[842]: I1006 09:20:04.691274 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"content\" (UniqueName: \"kubernetes.io/configmap/5e8de259-f3a2-490e-b885-c3ac2433099b-content\") pod \"helm-install-niks3-hc6hk\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") " pod="kube-system/helm-install-niks3-hc6hk"1602machine # [ 32.902625] k3s[842]: I1006 09:20:04.691292 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-57dhx\" (UniqueName: \"kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-kube-api-access-57dhx\") pod \"helm-install-niks3-hc6hk\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") " pod="kube-system/helm-install-niks3-hc6hk"1603machine # [ 32.989984] k3s[842]: I1006 09:20:04.815847 842 controller.go:667] quota admission added evaluator for: replicasets.apps1604machine # [ 33.072272] k3s[842]: time="2026-10-06T09:20:04Z" level=info msg="Tunnel authorizer set Kubelet Port 0.0.0.0:10250"1605machine # [ 33.210628] systemd[1]: Created slice libcontainer container kubepods-burstable-podbd03c376_8936_45ec_b7a8_d1a15859a19e.slice.1606machine # [ 33.277195] k3s[842]: E1006 09:20:05.103042 842 remote_runtime.go:237] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"13344f4f7f25f888604429b661c09a300a7a40c656116a8125467cd9ba580e83\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory"1607machine # [ 33.282151] k3s[842]: E1006 09:20:05.103169 842 kuberuntime_sandbox.go:70] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"13344f4f7f25f888604429b661c09a300a7a40c656116a8125467cd9ba580e83\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-hc6hk"1608machine # [ 33.287324] k3s[842]: E1006 09:20:05.103200 842 kuberuntime_manager.go:1640] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"13344f4f7f25f888604429b661c09a300a7a40c656116a8125467cd9ba580e83\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-hc6hk"1609machine # [ 33.292493] k3s[842]: E1006 09:20:05.103447 842 pod_workers.go:1338] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"helm-install-niks3-hc6hk_kube-system(5e8de259-f3a2-490e-b885-c3ac2433099b)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"helm-install-niks3-hc6hk_kube-system(5e8de259-f3a2-490e-b885-c3ac2433099b)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"13344f4f7f25f888604429b661c09a300a7a40c656116a8125467cd9ba580e83\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/helm-install-niks3-hc6hk" podUID="5e8de259-f3a2-490e-b885-c3ac2433099b"1610machine # [ 33.300948] k3s[842]: I1006 09:20:05.110316 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"config-volume\" (UniqueName: \"kubernetes.io/configmap/bd03c376-8936-45ec-b7a8-d1a15859a19e-config-volume\") pod \"coredns-54996dc9b4-kb66d\" (UID: \"bd03c376-8936-45ec-b7a8-d1a15859a19e\") " pod="kube-system/coredns-54996dc9b4-kb66d"1611machine # [ 33.305498] k3s[842]: I1006 09:20:05.110352 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-txxw5\" (UniqueName: \"kubernetes.io/projected/bd03c376-8936-45ec-b7a8-d1a15859a19e-kube-api-access-txxw5\") pod \"coredns-54996dc9b4-kb66d\" (UID: \"bd03c376-8936-45ec-b7a8-d1a15859a19e\") " pod="kube-system/coredns-54996dc9b4-kb66d"1612machine # [ 33.310143] k3s[842]: I1006 09:20:05.110373 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"custom-config-volume\" (UniqueName: \"kubernetes.io/configmap/bd03c376-8936-45ec-b7a8-d1a15859a19e-custom-config-volume\") pod \"coredns-54996dc9b4-kb66d\" (UID: \"bd03c376-8936-45ec-b7a8-d1a15859a19e\") " pod="kube-system/coredns-54996dc9b4-kb66d"1613machine # [ 33.314700] k3s[842]: I1006 09:20:05.118491 842 shared_informer.go:409] "Caches are synced"1614machine # [ 33.315833] k3s[842]: I1006 09:20:05.118516 842 garbagecollector.go:166] "Garbage collector: all resource monitors have synced"1615machine # [ 33.317438] k3s[842]: I1006 09:20:05.118522 842 garbagecollector.go:169] "Proceeding to collect garbage"1616machine # [ 33.318758] k3s[842]: I1006 09:20:05.138079 842 shared_informer.go:409] "Caches are synced"1617machine # Error from server (NotFound): namespaces "niks3" not found1618machine # [ 33.625477] k3s[842]: E1006 09:20:05.450826 842 remote_runtime.go:237] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"c99de5686fc55ab853e7d4ca1ccf9a856f1eb4b7b35940927f73c66978688e0b\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory"1619machine # [ 33.630243] k3s[842]: E1006 09:20:05.450938 842 kuberuntime_sandbox.go:70] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"c99de5686fc55ab853e7d4ca1ccf9a856f1eb4b7b35940927f73c66978688e0b\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-54996dc9b4-kb66d"1620machine # [ 33.635223] k3s[842]: E1006 09:20:05.450977 842 kuberuntime_manager.go:1640] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"c99de5686fc55ab853e7d4ca1ccf9a856f1eb4b7b35940927f73c66978688e0b\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-54996dc9b4-kb66d"1621machine # [ 33.640230] k3s[842]: E1006 09:20:05.451110 842 pod_workers.go:1338] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"coredns-54996dc9b4-kb66d_kube-system(bd03c376-8936-45ec-b7a8-d1a15859a19e)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"coredns-54996dc9b4-kb66d_kube-system(bd03c376-8936-45ec-b7a8-d1a15859a19e)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"c99de5686fc55ab853e7d4ca1ccf9a856f1eb4b7b35940927f73c66978688e0b\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/coredns-54996dc9b4-kb66d" podUID="bd03c376-8936-45ec-b7a8-d1a15859a19e"1622machine # [ 33.849854] k3s[842]: I1006 09:20:05.675638 842 kube.go:163] Node controller sync successful1623machine # [ 33.852100] k3s[842]: I1006 09:20:05.675812 842 vxlan.go:128] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false1624machine # [ 33.854781] k3s[842]: I1006 09:20:05.680139 842 kube.go:704] List of node(machine) annotations: map[string]string{"alpha.kubernetes.io/provided-node-ip":"10.0.2.15,fec0::87bf:b810:8c62:a860", "k3s.io/hostname":"machine", "k3s.io/internal-ip":"10.0.2.15,fec0::87bf:b810:8c62:a860", "k3s.io/node-args":"[\"server\",\"--disable\",\"traefik\",\"--disable\",\"metrics-server\",\"--disable\",\"local-storage\"]", "k3s.io/node-config-hash":"B5VKUCD5GTR3QGINHIAWYQ4H226RXO3OMZ3SDCJYGSY4JRMNFBRQ====", "k3s.io/node-env":"{}", "node.alpha.kubernetes.io/ttl":"0", "volumes.kubernetes.io/controller-managed-attach-detach":"true"}1625machine # [ 33.898108] (udev-worker)[1163]: Network interface NamePolicy= disabled on kernel command line.1626machine # [ 33.907586] k3s[842]: I1006 09:20:05.732965 842 iptables.go:50] Starting flannel in iptables mode...1627machine # [ 33.910907] k3s[842]: time="2026-10-06T09:20:05Z" level=warning msg="no subnet found for key: FLANNEL_NETWORK in file: /run/flannel/subnet.env"1628machine # [ 33.917376] k3s[842]: time="2026-10-06T09:20:05Z" level=warning msg="no subnet found for key: FLANNEL_SUBNET in file: /run/flannel/subnet.env"1629machine # [ 33.923877] k3s[842]: time="2026-10-06T09:20:05Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_NETWORK in file: /run/flannel/subnet.env"1630machine # [ 33.930207] k3s[842]: time="2026-10-06T09:20:05Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_SUBNET in file: /run/flannel/subnet.env"1631machine # [ 33.933474] k3s[842]: I1006 09:20:05.733144 842 iptables.go:101] Current network or subnet (10.42.0.0/16, 10.42.0.0/24) is not equal to previous one (0.0.0.0/0, 0.0.0.0/0), trying to recycle old iptables rules1632machine # [ 33.944490] k3s[842]: I1006 09:20:05.745163 842 kube.go:558] Creating the node lease for IPv4. This is the n.Spec.PodCIDRs: [10.42.0.0/24]1633machine # [ 33.959162] dhcpcd[578]: flannel.1: IAID 3a:3c:b2:451634machine # [ 33.960602] dhcpcd[578]: flannel.1: adding address fe80::80cf:3aff:fe3c:b2451635machine # [ 33.997501] k3s[842]: I1006 09:20:05.823361 842 iptables.go:111] Setting up masking rules1636machine # [ 34.011446] k3s[842]: I1006 09:20:05.837299 842 iptables.go:212] Changing default FORWARD chain policy to ACCEPT1637machine # [ 34.020307] k3s[842]: time="2026-10-06T09:20:05Z" level=info msg="Wrote flannel subnet file to /run/flannel/subnet.env"1638machine # [ 34.022649] k3s[842]: time="2026-10-06T09:20:05Z" level=info msg="Running flannel backend"1639machine # [ 34.024260] k3s[842]: I1006 09:20:05.846230 842 vxlan_network.go:68] watching for new subnet leases1640machine # [ 34.026266] k3s[842]: I1006 09:20:05.846259 842 vxlan_network.go:115] starting vxlan device watcher1641machine # [ 34.063742] k3s[842]: I1006 09:20:05.889596 842 iptables.go:358] bootstrap done1642machine # [ 34.094950] k3s[842]: I1006 09:20:05.920847 842 iptables.go:358] bootstrap done1643machine # [ 34.463588] dhcpcd[578]: flannel.1: soliciting a DHCP lease1644machine # Error from server (NotFound): namespaces "niks3" not found1645machine # [ 36.100489] k3s[842]: time="2026-10-06T09:20:07Z" level=info msg="Started tunnel to 10.0.2.15:6443"1646machine # [ 36.103062] k3s[842]: time="2026-10-06T09:20:07Z" level=info msg="Stopped tunnel to 127.0.0.1:6443"1647machine # [ 36.105082] k3s[842]: time="2026-10-06T09:20:07Z" level=info msg="Connecting to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1648machine # [ 36.108328] k3s[842]: time="2026-10-06T09:20:07Z" level=info msg="Proxy done" err="context canceled" url="wss://127.0.0.1:6443/v1-k3s/connect"1649machine # Error from server (NotFound): namespaces "niks3" not found1650machine # [ 36.111237] k3s[842]: time="2026-10-06T09:20:07Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF"1651machine # [ 36.116252] k3s[842]: time="2026-10-06T09:20:07Z" level=info msg="Handling backend connection request [machine]"1652machine # [ 36.117704] k3s[842]: time="2026-10-06T09:20:07Z" level=info msg="Connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1653machine # [ 36.119316] k3s[842]: time="2026-10-06T09:20:07Z" level=info msg="Remotedialer connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1654machine # [ 36.459195] dhcpcd[578]: flannel.1: soliciting an IPv6 router1655machine # Error from server (NotFound): namespaces "niks3" not found1656machine # [ 38.087844] k3s[842]: I1006 09:20:09.912623 842 kuberuntime_manager.go:2172] "Updating runtime config through cri with podcidr" CIDR="10.42.0.0/24"1657machine # [ 38.089158] k3s[842]: I1006 09:20:09.914156 842 kubelet_network.go:48] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="10.42.0.0/24"1658machine # Error from server (NotFound): namespaces "niks3" not found1659machine # [ 38.965338] k3s[842]: time="2026-10-06T09:20:10Z" level=info msg="Starting network policy controller version v2.6.3-k3s1, built on 1970-01-01T01:01:01Z, go1.26.8"1660machine # [ 38.968759] k3s[842]: I1006 09:20:10.791199 842 network_policy_controller.go:164] Starting network policy controller1661machine # [ 39.143723] k3s[842]: I1006 09:20:10.969170 842 network_policy_controller.go:179] Starting network policy controller full sync goroutine1662machine # [ 39.466031] dhcpcd[578]: flannel.1: probing for an IPv4LL address1663machine # Error from server (NotFound): namespaces "niks3" not found1664machine # Error from server (NotFound): namespaces "niks3" not found1665machine # Error from server (NotFound): namespaces "niks3" not found1666machine # Error from server (NotFound): namespaces "niks3" not found1667machine # [ 44.578069] dhcpcd[578]: flannel.1: using IPv4LL address 169.254.103.1861668machine # [ 44.578268] dhcpcd[578]: flannel.1: adding route to 169.254.0.0/161669machine # Error from server (NotFound): namespaces "niks3" not found1670machine # Error from server (NotFound): namespaces "niks3" not found1671machine # [ 46.513091] cni0: port 1(veth2baa68b2) entered blocking state1672machine # [ 46.513131] cni0: port 1(veth2baa68b2) entered disabled state1673machine # [ 46.513166] veth2baa68b2: entered allmulticast mode1674machine # [ 46.513305] veth2baa68b2: entered promiscuous mode1675machine # [ 46.516836] cni0: port 2(vethe61e3b7e) entered blocking state1676machine # [ 46.516867] cni0: port 2(vethe61e3b7e) entered disabled state1677machine # [ 46.516904] vethe61e3b7e: entered allmulticast mode1678machine # [ 46.517010] vethe61e3b7e: entered promiscuous mode1679machine # [ 46.550146] cni0: port 2(vethe61e3b7e) entered blocking state1680machine # [ 46.550175] cni0: port 2(vethe61e3b7e) entered forwarding state1681machine # [ 46.560386] cni0: port 1(veth2baa68b2) entered blocking state1682machine # [ 46.560418] cni0: port 1(veth2baa68b2) entered forwarding state1683machine # [ 46.592092] (udev-worker)[1630]: Network interface NamePolicy= disabled on kernel command line.1684machine # [ 46.606099] (udev-worker)[1634]: Network interface NamePolicy= disabled on kernel command line.1685machine # [ 46.609284] (udev-worker)[1638]: Network interface NamePolicy= disabled on kernel command line.1686machine # [ 46.654955] dhcpcd[578]: veth2baa68b2: IAID 25:53:ae:f31687machine # [ 46.656609] dhcpcd[578]: veth2baa68b2: adding address fe80::b41b:25ff:fe53:aef31688machine # [ 46.671041] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount1795131766.mount: Deactivated successfully.1689machine # [ 46.698622] dhcpcd[578]: vethe61e3b7e: IAID 97:7b:09:2c1690machine # [ 46.699760] dhcpcd[578]: vethe61e3b7e: adding address fe80::381d:97ff:fe7b:92c1691machine # [ 46.715644] dhcpcd[578]: vethe61e3b7e: soliciting a DHCP lease1692machine # [ 46.780666] systemd[1]: Started libcontainer container 64869ade4305c25e0c5735dbbdcdc7f1d8e2237b93ee99303ac42c4b4e4f973c.1693machine # [ 46.785087] systemd[1]: Started libcontainer container ee9771951b096586c70fe5cf9d73c6a776655c44abcbb2e6dc01dcc4a89097f9.1694machine # Error from server (NotFound): namespaces "niks3" not found1695machine # [ 47.731044] dhcpcd[578]: veth2baa68b2: soliciting a DHCP lease1696machine # [ 48.441588] systemd[1]: Started libcontainer container 61fe514dd6b60ed1d2f4ac9545807c4b14d1b4a331e4e8eaa3bdc5530a3267cc.1697machine # Error from server (NotFound): namespaces "niks3" not found1698machine # [ 48.464750] dhcpcd[578]: flannel.1: no IPv6 Routers available1699machine # [ 48.571011] k3s[842]: I1006 09:20:20.396356 842 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/coredns-54996dc9b4-kb66d" podStartSLOduration=16.39633438 podStartE2EDuration="16.39633438s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-10-06 09:20:04 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-10-06 09:20:20.39371176 +0000 UTC m=+30.371591241" watchObservedRunningTime="2026-10-06 09:20:20.39633438 +0000 UTC m=+30.374213861"1700machine # [ 48.636815] dhcpcd[578]: vethe61e3b7e: soliciting an IPv6 router1701machine # [ 48.682153] dhcpcd[578]: veth2baa68b2: soliciting an IPv6 router1702machine # [ 48.812456] systemd[1]: Started libcontainer container 321af33c96b8a76ca1765670dc2240281630ebf12221998a289396e642cb2f27.1703machine # [ 48.925128] k3s[842]: I1006 09:20:20.750236 842 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/helm-install-niks3-hc6hk" podStartSLOduration=16.75021342 podStartE2EDuration="16.75021342s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-10-06 09:20:04 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-10-06 09:20:20.74938654 +0000 UTC m=+30.727266021" watchObservedRunningTime="2026-10-06 09:20:20.75021342 +0000 UTC m=+30.728092901"1704machine # Error from server (NotFound): namespaces "niks3" not found1705machine # [ 50.169239] k3s[842]: I1006 09:20:21.994584 842 alloc.go:329] "allocated clusterIPs" service="niks3/niks3" clusterIPs={"IPv4":"10.43.22.202"}1706machine # [ 50.203614] k3s[842]: I1006 09:20:22.029486 842 controller.go:667] quota admission added evaluator for: cronjobs.batch1707machine # [ 50.244195] systemd[1]: cri-containerd-321af33c96b8a76ca1765670dc2240281630ebf12221998a289396e642cb2f27.scope: Deactivated successfully.1708machine # [ 50.245943] systemd[1]: cri-containerd-321af33c96b8a76ca1765670dc2240281630ebf12221998a289396e642cb2f27.scope: Consumed 845ms CPU time over 1.430s wall clock time, 38.2M memory peak, 4.5M incoming IP traffic, 96.5K outgoing IP traffic.1709machine # [ 50.286014] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-321af33c96b8a76ca1765670dc2240281630ebf12221998a289396e642cb2f27-rootfs.mount: Deactivated successfully.1710machine # [ 50.408483] k3s[842]: E1006 09:20:22.234307 842 replica_set.go:640] "Unhandled Error" err="sync \"niks3/niks3-5b6bd764d7\" failed with read version: 446 is not as new as written version: 455 for group resource replicasets.apps" logger="UnhandledError"1711machine # [ 50.439286] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod57f6361b_a4f7_4965_a667_4d25044bf676.slice.1712machine # [ 50.505736] k3s[842]: I1006 09:20:22.331597 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"db\" (UniqueName: \"kubernetes.io/secret/57f6361b-a4f7-4965-a667-4d25044bf676-db\") pod \"niks3-5b6bd764d7-nj287\" (UID: \"57f6361b-a4f7-4965-a667-4d25044bf676\") " pod="niks3/niks3-5b6bd764d7-nj287"1713machine # [ 50.509999] k3s[842]: I1006 09:20:22.331645 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"s3\" (UniqueName: \"kubernetes.io/secret/57f6361b-a4f7-4965-a667-4d25044bf676-s3\") pod \"niks3-5b6bd764d7-nj287\" (UID: \"57f6361b-a4f7-4965-a667-4d25044bf676\") " pod="niks3/niks3-5b6bd764d7-nj287"1714machine # [ 50.514028] k3s[842]: I1006 09:20:22.331677 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-t7xl9\" (UniqueName: \"kubernetes.io/projected/57f6361b-a4f7-4965-a667-4d25044bf676-kube-api-access-t7xl9\") pod \"niks3-5b6bd764d7-nj287\" (UID: \"57f6361b-a4f7-4965-a667-4d25044bf676\") " pod="niks3/niks3-5b6bd764d7-nj287"1715machine # [ 50.518425] k3s[842]: I1006 09:20:22.331696 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"oidc\" (UniqueName: \"kubernetes.io/configmap/57f6361b-a4f7-4965-a667-4d25044bf676-oidc\") pod \"niks3-5b6bd764d7-nj287\" (UID: \"57f6361b-a4f7-4965-a667-4d25044bf676\") " pod="niks3/niks3-5b6bd764d7-nj287"1716machine # [ 50.522541] k3s[842]: I1006 09:20:22.331712 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/57f6361b-a4f7-4965-a667-4d25044bf676-token\") pod \"niks3-5b6bd764d7-nj287\" (UID: \"57f6361b-a4f7-4965-a667-4d25044bf676\") " pod="niks3/niks3-5b6bd764d7-nj287"1717machine # [ 50.809581] cni0: port 3(vethd8b72deb) entered blocking state1718machine # [ 50.809622] cni0: port 3(vethd8b72deb) entered disabled state1719machine # [ 50.809666] vethd8b72deb: entered allmulticast mode1720machine # [ 50.809815] vethd8b72deb: entered promiscuous mode1721machine # [ 50.853788] cni0: port 3(vethd8b72deb) entered blocking state1722machine # [ 50.853820] cni0: port 3(vethd8b72deb) entered forwarding state1723machine # [ 50.890504] (udev-worker)[2077]: Network interface NamePolicy= disabled on kernel command line.1724machine # [ 50.945346] dhcpcd[578]: vethd8b72deb: IAID bd:31:a3:361725machine # [ 50.946252] dhcpcd[578]: vethd8b72deb: adding address fe80::70fd:bdff:fe31:a3361726machine # [ 51.060843] systemd[1]: Started libcontainer container de5f981fbdb7ef9ffcfa6444529fee54d50118003b536d428154da6dbb949a4b.1727machine # [ 51.099267] dhcpcd[578]: vethd8b72deb: soliciting a DHCP lease1728machine # [ 51.520789] systemd[1]: Started libcontainer container 0d62fc4cc772ffb64e62fb5a7053775f99b3297e7575f6d1f6f591776765e905.1729machine # [ 51.628580] k3s[842]: I1006 09:20:23.453557 842 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/niks3-5b6bd764d7-nj287" podStartSLOduration=1.45352928 podStartE2EDuration="1.45352928s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-10-06 09:20:22 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-10-06 09:20:23.45116122 +0000 UTC m=+33.429040701" watchObservedRunningTime="2026-10-06 09:20:23.45352928 +0000 UTC m=+33.431408761"1730machine # [ 51.671640] systemd[1]: cri-containerd-ee9771951b096586c70fe5cf9d73c6a776655c44abcbb2e6dc01dcc4a89097f9.scope: Deactivated successfully.1731machine # [ 51.716377] dhcpcd[578]: vethe61e3b7e: probing for an IPv4LL address1732machine # [ 51.749695] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-ee9771951b096586c70fe5cf9d73c6a776655c44abcbb2e6dc01dcc4a89097f9-rootfs.mount: Deactivated successfully.1733machine # [ 51.842106] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-ee9771951b096586c70fe5cf9d73c6a776655c44abcbb2e6dc01dcc4a89097f9-shm.mount: Deactivated successfully.1734machine # [ 51.890748] dhcpcd[578]: vethe61e3b7e: carrier lost[ 51.893828] cni0: port 2(vethe61e3b7e) entered disabled state1735machine # 1736machine # [ 51.897164] vethe61e3b7e (unregistering): left allmulticast mode1737machine # [ 51.897187] vethe61e3b7e (unregistering): left promiscuous mode1738machine # [ 51.897200] cni0: port 2(vethe61e3b7e) entered disabled state1739machine # [ 51.933651] systemd[1]: run-netns-cni\x2dab9e2b57\x2d06b0\x2da49c\x2d64fe\x2da5440a800c4f.mount: Deactivated successfully.1740machine # [ 51.947027] dhcpcd[578]: vethe61e3b7e: deleting address fe80::381d:97ff:fe7b:92c1741machine # [ 52.004688] dhcpcd[578]: vethe61e3b7e: removing interface1742machine # [ 52.019758] k3s[842]: I1006 09:20:23.845629 842 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-kube-api-access-57dhx\" (UniqueName: \"kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-kube-api-access-57dhx\") pod \"5e8de259-f3a2-490e-b885-c3ac2433099b\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") "1743machine # [ 52.025218] k3s[842]: I1006 09:20:23.850487 842 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/configmap/5e8de259-f3a2-490e-b885-c3ac2433099b-content\" (UniqueName: \"kubernetes.io/configmap/5e8de259-f3a2-490e-b885-c3ac2433099b-content\") pod \"5e8de259-f3a2-490e-b885-c3ac2433099b\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") "1744machine # [ 52.030489] k3s[842]: I1006 09:20:23.850536 842 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-config\") pod \"5e8de259-f3a2-490e-b885-c3ac2433099b\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") "1745machine # [ 52.036126] k3s[842]: I1006 09:20:23.850555 842 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-tmp\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-tmp\") pod \"5e8de259-f3a2-490e-b885-c3ac2433099b\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") "1746machine # [ 52.045886] k3s[842]: I1006 09:20:23.850590 842 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-values\" (UniqueName: \"kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-values\") pod \"5e8de259-f3a2-490e-b885-c3ac2433099b\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") "1747machine # [ 52.051065] k3s[842]: I1006 09:20:23.850622 842 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-helm\") pod \"5e8de259-f3a2-490e-b885-c3ac2433099b\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") "1748machine # [ 52.055810] k3s[842]: I1006 09:20:23.850639 842 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-cache\") pod \"5e8de259-f3a2-490e-b885-c3ac2433099b\" (UID: \"5e8de259-f3a2-490e-b885-c3ac2433099b\") "1749machine # [ 52.060965] k3s[842]: I1006 09:20:23.851021 842 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/configmap/5e8de259-f3a2-490e-b885-c3ac2433099b-content" pod "5e8de259-f3a2-490e-b885-c3ac2433099b" (UID: "5e8de259-f3a2-490e-b885-c3ac2433099b"). InnerVolumeSpecName "content". PluginName "kubernetes.io/configmap", VolumeGIDValue ""1750machine # [ 52.065519] k3s[842]: I1006 09:20:23.861670 842 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-config" pod "5e8de259-f3a2-490e-b885-c3ac2433099b" (UID: "5e8de259-f3a2-490e-b885-c3ac2433099b"). InnerVolumeSpecName "klipper-config". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1751machine # [ 52.070134] k3s[842]: I1006 09:20:23.869415 842 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-tmp" pod "5e8de259-f3a2-490e-b885-c3ac2433099b" (UID: "5e8de259-f3a2-490e-b885-c3ac2433099b"). InnerVolumeSpecName "tmp". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1752machine # [ 52.074448] k3s[842]: I1006 09:20:23.871271 842 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-kube-api-access-57dhx" pod "5e8de259-f3a2-490e-b885-c3ac2433099b" (UID: "5e8de259-f3a2-490e-b885-c3ac2433099b"). InnerVolumeSpecName "kube-api-access-57dhx". PluginName "kubernetes.io/projected", VolumeGIDValue ""1753machine # [ 52.079223] k3s[842]: I1006 09:20:23.872003 842 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-values" pod "5e8de259-f3a2-490e-b885-c3ac2433099b" (UID: "5e8de259-f3a2-490e-b885-c3ac2433099b"). InnerVolumeSpecName "values". PluginName "kubernetes.io/projected", VolumeGIDValue ""1754machine # [ 52.083696] k3s[842]: I1006 09:20:23.876546 842 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-cache" pod "5e8de259-f3a2-490e-b885-c3ac2433099b" (UID: "5e8de259-f3a2-490e-b885-c3ac2433099b"). InnerVolumeSpecName "klipper-cache". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1755machine # [ 52.088326] k3s[842]: I1006 09:20:23.876873 842 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-helm" pod "5e8de259-f3a2-490e-b885-c3ac2433099b" (UID: "5e8de259-f3a2-490e-b885-c3ac2433099b"). InnerVolumeSpecName "klipper-helm". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1756machine # [ 52.124982] k3s[842]: I1006 09:20:23.950814 842 reconciler_common.go:299] "Volume detached for volume \"kube-api-access-57dhx\" (UniqueName: \"kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-kube-api-access-57dhx\") on node \"machine\" DevicePath \"\""1757machine # [ 52.128292] k3s[842]: I1006 09:20:23.950846 842 reconciler_common.go:299] "Volume detached for volume \"content\" (UniqueName: \"kubernetes.io/configmap/5e8de259-f3a2-490e-b885-c3ac2433099b-content\") on node \"machine\" DevicePath \"\""1758machine # [ 52.130990] k3s[842]: I1006 09:20:23.950857 842 reconciler_common.go:299] "Volume detached for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-config\") on node \"machine\" DevicePath \"\""1759machine # [ 52.133945] k3s[842]: I1006 09:20:23.950866 842 reconciler_common.go:299] "Volume detached for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-tmp\") on node \"machine\" DevicePath \"\""1760machine # [ 52.136736] k3s[842]: I1006 09:20:23.950874 842 reconciler_common.go:299] "Volume detached for volume \"values\" (UniqueName: \"kubernetes.io/projected/5e8de259-f3a2-490e-b885-c3ac2433099b-values\") on node \"machine\" DevicePath \"\""1761machine # [ 52.139467] k3s[842]: I1006 09:20:23.950895 842 reconciler_common.go:299] "Volume detached for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-helm\") on node \"machine\" DevicePath \"\""1762machine # [ 52.142462] k3s[842]: I1006 09:20:23.950903 842 reconciler_common.go:299] "Volume detached for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/5e8de259-f3a2-490e-b885-c3ac2433099b-klipper-cache\") on node \"machine\" DevicePath \"\""1763machine # [ 52.286989] systemd[1]: var-lib-kubelet-pods-5e8de259\x2df3a2\x2d490e\x2db885\x2dc3ac2433099b-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dconfig.mount: Deactivated successfully.1764machine # [ 52.290799] systemd[1]: var-lib-kubelet-pods-5e8de259\x2df3a2\x2d490e\x2db885\x2dc3ac2433099b-volumes-kubernetes.io\x7eprojected-kube\x2dapi\x2daccess\x2d57dhx.mount: Deactivated successfully.1765machine # [ 52.294548] systemd[1]: var-lib-kubelet-pods-5e8de259\x2df3a2\x2d490e\x2db885\x2dc3ac2433099b-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dcache.mount: Deactivated successfully.1766machine # [ 52.298095] systemd[1]: var-lib-kubelet-pods-5e8de259\x2df3a2\x2d490e\x2db885\x2dc3ac2433099b-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dhelm.mount: Deactivated successfully.1767machine # [ 52.301529] systemd[1]: var-lib-kubelet-pods-5e8de259\x2df3a2\x2d490e\x2db885\x2dc3ac2433099b-volumes-kubernetes.io\x7eprojected-values.mount: Deactivated successfully.1768machine # [ 52.305498] systemd[1]: var-lib-kubelet-pods-5e8de259\x2df3a2\x2d490e\x2db885\x2dc3ac2433099b-volumes-kubernetes.io\x7eempty\x2ddir-tmp.mount: Deactivated successfully.1769machine # [ 52.642338] k3s[842]: I1006 09:20:24.467484 842 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="ee9771951b096586c70fe5cf9d73c6a776655c44abcbb2e6dc01dcc4a89097f9"1770machine # [ 52.656779] systemd[1]: Removed slice libcontainer container kubepods-burstable-pod5e8de259_f3a2_490e_b885_c3ac2433099b.slice.1771machine # [ 52.659375] systemd[1]: kubepods-burstable-pod5e8de259_f3a2_490e_b885_c3ac2433099b.slice: Consumed 873ms CPU time over 19.826s wall clock time, 38.4M memory peak, 4.5M incoming IP traffic, 96.5K outgoing IP traffic.1772machine # [ 52.731595] dhcpcd[578]: veth2baa68b2: probing for an IPv4LL address1773machine # [ 53.309493] dhcpcd[578]: vethd8b72deb: soliciting an IPv6 router1774machine # [ 56.101811] dhcpcd[578]: vethd8b72deb: probing for an IPv4LL address1775machine: (finished: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s, in 28.49 seconds)1776machine: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true1777machine: (finished: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true, in 0.19 seconds)1778machine: waiting for success: curl -sf http://localhost:30051/readyz | grep OK1779machine: (finished: waiting for success: curl -sf http://localhost:30051/readyz | grep OK, in 0.04 seconds)1780(finished: subtest: chart deploys and becomes ready, in 28.71 seconds)1781machine: waiting for success: kubectl -n ci get sa builder1782machine: (finished: waiting for success: kubectl -n ci get sa builder, in 0.18 seconds)1783machine: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt1784machine # [ 57.233551] dhcpcd[578]: veth2baa68b2: using IPv4LL address 169.254.149.1591785machine # [ 57.236457] dhcpcd[578]: veth2baa68b2: adding route to 169.254.0.0/161786machine: (finished: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt, in 0.19 seconds)1787machine: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt1788machine: (finished: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt, in 0.17 seconds)1789machine: must succeed: readlink -f /run/current-system/sw/bin/niks31790machine: (finished: must succeed: readlink -f /run/current-system/sw/bin/niks3, in 0.02 seconds)1791subtest: allowed service account can push via workload identity1792machine: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/vr887zd4l0370dnc4hkmjy817sgpdv05-niks3-1.13.0 2>&11793machine: (finished: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/vr887zd4l0370dnc4hkmjy817sgpdv05-niks3-1.13.0 2>&1, in 1.07 seconds)1794machine: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/vr887zd4l0370dnc4hkmjy817sgpdv05.narinfo1795machine: (finished: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/vr887zd4l0370dnc4hkmjy817sgpdv05.narinfo, in 0.03 seconds)1796(finished: subtest: allowed service account can push via workload identity, in 1.10 seconds)1797subtest: write scope does not grant admin1798machine: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status1799machine: (finished: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status, in 0.03 seconds)1800(finished: subtest: write scope does not grant admin, in 0.03 seconds)1801subtest: other service accounts are rejected1802machine: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/vr887zd4l0370dnc4hkmjy817sgpdv05-niks3-1.13.0 2>&11803machine: (finished: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/vr887zd4l0370dnc4hkmjy817sgpdv05-niks3-1.13.0 2>&1, in 0.12 seconds)1804(finished: subtest: other service accounts are rejected, in 0.12 seconds)1805subtest: gc cronjob runs against the service1806machine: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual1807machine: (finished: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual, in 0.18 seconds)1808machine: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s1809machine # [ 58.966183] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod5695f044_2e68_4675_8110_603817332905.slice.1810machine # [ 58.968462] k3s[842]: I1006 09:20:30.791947 842 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/5695f044-2e68-4675-8110-603817332905-token\") pod \"gc-manual-rd2hp\" (UID: \"5695f044-2e68-4675-8110-603817332905\") " pod="niks3/gc-manual-rd2hp"1811machine # [ 59.331027] cni0: port 2(veth7f32f141) entered blocking state1812machine # [ 59.331062] cni0: port 2(veth7f32f141) entered disabled state1813machine # [ 59.331095] veth7f32f141: entered allmulticast mode1814machine # [ 59.331224] veth7f32f141: entered promiscuous mode1815machine # [ 59.352749] cni0: port 2(veth7f32f141) entered blocking state1816machine # [ 59.352783] cni0: port 2(veth7f32f141) entered forwarding state1817machine # [ 59.412930] (udev-worker)[2574]: Network interface NamePolicy= disabled on kernel command line.1818machine # [ 59.463046] dhcpcd[578]: veth7f32f141: IAID 29:59:9f:f31819machine # [ 59.463945] dhcpcd[578]: veth7f32f141: adding address fe80::8872:29ff:fe59:9ff31820machine # [ 59.504451] systemd[1]: Started libcontainer container 5a48b3c2ff1c0587d4c317f2ea4cfbb22372e3a31211f6841628b74819b47f2b.1821machine # [ 59.632693] systemd[1]: Started libcontainer container 39a489ec7bfd847cc8798bdf9c0681a3f4ea0759d23b87652aa3900588f34c84.1822machine # [ 60.542432] dhcpcd[578]: veth7f32f141: soliciting a DHCP lease1823machine # [ 60.684716] dhcpcd[578]: veth2baa68b2: no IPv6 Routers available1824machine # [ 60.708888] dhcpcd[578]: vethd8b72deb: using IPv4LL address 169.254.8.2481825machine # [ 60.710631] dhcpcd[578]: vethd8b72deb: adding route to 169.254.0.0/161826machine # [ 60.744402] dhcpcd[578]: veth7f32f141: soliciting an IPv6 router1827machine # [ 61.720629] systemd[1]: cri-containerd-39a489ec7bfd847cc8798bdf9c0681a3f4ea0759d23b87652aa3900588f34c84.scope: Deactivated successfully.1828machine # [ 61.720904] systemd[1]: cri-containerd-39a489ec7bfd847cc8798bdf9c0681a3f4ea0759d23b87652aa3900588f34c84.scope: Consumed 49ms CPU time over 2.086s wall clock time, 15.1M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic.1829machine # [ 61.779235] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-39a489ec7bfd847cc8798bdf9c0681a3f4ea0759d23b87652aa3900588f34c84-rootfs.mount: Deactivated successfully.1830machine # [ 63.705025] systemd[1]: cri-containerd-5a48b3c2ff1c0587d4c317f2ea4cfbb22372e3a31211f6841628b74819b47f2b.scope: Deactivated successfully.1831machine # [ 63.759200] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-5a48b3c2ff1c0587d4c317f2ea4cfbb22372e3a31211f6841628b74819b47f2b-rootfs.mount: Deactivated successfully.1832machine # [ 63.804965] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-5a48b3c2ff1c0587d4c317f2ea4cfbb22372e3a31211f6841628b74819b47f2b-shm.mount: Deactivated successfully.1833machine # [ 63.854647] cni0: port 2(veth7f32f141) entered disabled state1834machine # [ 63.852776] dhcpcd[578]: veth7f32f141: carrier lost1835machine # [ 63.857834] veth7f32f141 (unregistering): left allmulticast mode1836machine # [ 63.857868] veth7f32f141 (unregistering): left promiscuous mode1837machine # [ 63.857887] cni0: port 2(veth7f32f141) entered disabled state1838machine # [ 63.894175] systemd[1]: run-netns-cni\x2d788e383c\x2d8d5d\x2d5f2f\x2d9a57\x2d62bd2fc8eae6.mount: Deactivated successfully.1839machine # [ 63.913779] dhcpcd[578]: veth7f32f141: deleting address fe80::8872:29ff:fe59:9ff31840machine # [ 63.972565] dhcpcd[578]: veth7f32f141: removing interface1841machine # [ 63.998971] k3s[842]: I1006 09:20:35.824464 842 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/secret/5695f044-2e68-4675-8110-603817332905-token\" (UniqueName: \"kubernetes.io/secret/5695f044-2e68-4675-8110-603817332905-token\") pod \"5695f044-2e68-4675-8110-603817332905\" (UID: \"5695f044-2e68-4675-8110-603817332905\") "1842machine # [ 64.007539] systemd[1]: var-lib-kubelet-pods-5695f044\x2d2e68\x2d4675\x2d8110\x2d603817332905-volumes-kubernetes.io\x7esecret-token.mount: Deactivated successfully.1843machine # [ 64.010007] k3s[842]: I1006 09:20:35.833866 842 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/5695f044-2e68-4675-8110-603817332905-token" pod "5695f044-2e68-4675-8110-603817332905" (UID: "5695f044-2e68-4675-8110-603817332905"). InnerVolumeSpecName "token". PluginName "kubernetes.io/secret", VolumeGIDValue ""1844machine # [ 64.099613] k3s[842]: I1006 09:20:35.925494 842 reconciler_common.go:299] "Volume detached for volume \"token\" (UniqueName: \"kubernetes.io/secret/5695f044-2e68-4675-8110-603817332905-token\") on node \"machine\" DevicePath \"\""1845machine # [ 64.688125] k3s[842]: I1006 09:20:36.509170 842 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="5a48b3c2ff1c0587d4c317f2ea4cfbb22372e3a31211f6841628b74819b47f2b"1846machine # [ 64.701249] systemd[1]: Removed slice libcontainer container kubepods-besteffort-pod5695f044_2e68_4675_8110_603817332905.slice.1847machine # [ 64.705778] systemd[1]: kubepods-besteffort-pod5695f044_2e68_4675_8110_603817332905.slice: Consumed 82ms CPU time over 5.734s wall clock time, 16M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic.1848machine: (finished: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s, in 5.82 seconds)1849(finished: subtest: gc cronjob runs against the service, in 6.00 seconds)1850subtest: helm test hook passes1851machine: must succeed: helm test -n niks3 niks3 --timeout 2m >&21852machine # [ 65.312062] dhcpcd[578]: vethd8b72deb: no IPv6 Routers available1853machine # [ 65.467190] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod58c6264d_fd1e_46e0_8e04_ba88fa8dc100.slice.1854machine # [ 65.518051] (udev-worker)[2785]: Network interface NamePolicy= disabled on kernel command line.1855machine # [ 65.524048] cni0: port 2(veth85a9b18d) entered blocking state1856machine # [ 65.524078] cni0: port 2(veth85a9b18d) entered disabled state1857machine # [ 65.524114] veth85a9b18d: entered allmulticast mode1858machine # [ 65.524216] veth85a9b18d: entered promiscuous mode1859machine # [ 65.551802] cni0: port 2(veth85a9b18d) entered blocking state1860machine # [ 65.551828] cni0: port 2(veth85a9b18d) entered forwarding state1861machine # [ 65.603411] dhcpcd[578]: veth85a9b18d: waiting for carrier1862machine # [ 65.604375] dhcpcd[578]: veth85a9b18d: carrier acquired1863machine # [ 65.611894] dhcpcd[578]: veth85a9b18d: IAID 75:46:63:c21864machine # [ 65.613206] dhcpcd[578]: veth85a9b18d: adding address fe80::421:75ff:fe46:63c21865machine # [ 65.713028] systemd[1]: Started libcontainer container 534791e888429385884f916c3ac844bb481569074f586eddb487f1573a5653e2.1866machine # [ 65.842047] systemd[1]: Started libcontainer container 55c5175da3d2d1d40204c2d7c1e5d349cbaf07a231cf1e8290de830788934ce9.1867machine # [ 65.914028] systemd[1]: cri-containerd-55c5175da3d2d1d40204c2d7c1e5d349cbaf07a231cf1e8290de830788934ce9.scope: Deactivated successfully.1868machine # [ 65.916330] systemd[1]: cri-containerd-55c5175da3d2d1d40204c2d7c1e5d349cbaf07a231cf1e8290de830788934ce9.scope: Consumed 31ms CPU time over 72ms wall clock time, 14.1M memory peak, 641B incoming IP traffic, 547B outgoing IP traffic.1869machine # [ 65.942696] k3s[842]: I1006 09:20:37.767921 842 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/niks3-test" podStartSLOduration=0.76789966 podStartE2EDuration="767.89966ms" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-10-06 09:20:37 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-10-06 09:20:37.76764716 +0000 UTC m=+47.745526641" watchObservedRunningTime="2026-10-06 09:20:37.76789966 +0000 UTC m=+47.745779141"1870machine # [ 65.967361] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-55c5175da3d2d1d40204c2d7c1e5d349cbaf07a231cf1e8290de830788934ce9-rootfs.mount: Deactivated successfully.1871machine # [ 67.523302] dhcpcd[578]: veth85a9b18d: soliciting a DHCP lease1872machine # [ 67.715629] systemd[1]: cri-containerd-534791e888429385884f916c3ac844bb481569074f586eddb487f1573a5653e2.scope: Deactivated successfully.1873machine # [ 67.763712] dhcpcd[578]: veth85a9b18d: soliciting an IPv6 router1874machine # [ 67.787166] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-534791e888429385884f916c3ac844bb481569074f586eddb487f1573a5653e2-rootfs.mount: Deactivated successfully.1875machine # [ 67.823122] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-534791e888429385884f916c3ac844bb481569074f586eddb487f1573a5653e2-shm.mount: Deactivated successfully.1876machine # [ 67.869594] dhcpcd[578]: veth85a9b18d: carrier lost1877machine # [ 67.872300] cni0: port 2(veth85a9b18d) entered disabled state1878machine # [ 67.873705] veth85a9b18d (unregistering): left allmulticast mode1879machine # [ 67.873734] veth85a9b18d (unregistering): left promiscuous mode1880machine # [ 67.873747] cni0: port 2(veth85a9b18d) entered disabled state1881machine # [ 67.910634] systemd[1]: run-netns-cni\x2d362e5fe3\x2d1e6f\x2d4f27\x2d18c8\x2d7402911a957b.mount: Deactivated successfully.1882machine # [ 67.917709] dhcpcd[578]: veth85a9b18d: deleting address fe80::421:75ff:fe46:63c21883machine # NAME: niks31884machine # LAST DEPLOYED: Tue Oct 6 09:20:21 20261885machine # NAMESPACE: niks31886machine # STATUS: deployed1887machine # REVISION: 11888machine # DESCRIPTION: Install complete1889machine # TEST SUITE: niks3-test1890machine # Last Started: Tue Oct 6 09:20:37 20261891machine # Last Completed: Tue Oct 6 09:20:39 20261892machine # Phase: Succeeded1893machine # [ 67.999655] dhcpcd[578]: veth85a9b18d: removing interface1894machine: (finished: must succeed: helm test -n niks3 niks3 --timeout 2m >&2, in 3.25 seconds)1895(finished: subtest: helm test hook passes, in 3.25 seconds)1896(finished: run the VM test script, in 69.08 seconds)1897test script finished in 69.11s1898cleanup1899kill QemuMachine (pid 45)1900machine # qemu-system-aarch64: terminating on signal 15 from pid 39 (/nix/store/81ag9nxz1flw3xjkv1vvqg8y2ipx2ins-python3-3.14.7/bin/python3.14)1901machine # [2026-10-06T09:20:39Z INFO virtiofsd] Client disconnected, shutting down1902machine # [2026-10-06T09:20:39Z INFO virtiofsd] Client disconnected, shutting down1903machine # [2026-10-06T09:20:39Z INFO virtiofsd] Client disconnected, shutting down1904(finished: cleanup, in 0.84 seconds)1905additionally exposed symbols:1906 machine,1907 vlan1,1908 start_all, test_script, machines, machines_qemu, machines_nspawn, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, BaseMachine, QemuMachine, NspawnMachine, t, debug, dump_machine_ssh1909time=2026-10-06T09:20:29.499Z level=INFO msg="Uploading 8 paths to localhost (0 already cached)"1910time=2026-10-06T09:20:29.499Z level=INFO msg="Uploading d3xvwgga6f7mchrbvc77g3gap2yw1pd4-libunistring-1.4.2 (2.0MB)"1911time=2026-10-06T09:20:29.499Z level=INFO msg="Uploading xpzpw9ik1hwrb2dvsybgi5pwb3xmf5rl-mailcap-2.1.54 (116.6KB)"1912time=2026-10-06T09:20:29.499Z level=INFO msg="Uploading 5g0149dc72bz1rdxjc10qnr4vdh9yp1x-tzdata-2026d (2.0MB)"1913time=2026-10-06T09:20:29.499Z level=INFO msg="Uploading n9ggd62fbgfy5f936vfisxgcdic3v9z1-iana-etc-20251215 (557.8KB)"1914time=2026-10-06T09:20:29.499Z level=INFO msg="Uploading ficwc08a9q1rigvr4jv9l3xsvmx3yfqn-xgcc-16.2.0-libgcc (150.2KB)"1915time=2026-10-06T09:20:29.500Z level=INFO msg="Uploading gxljc46qyjqzvhrnf5wk5ypyg73qv84n-libidn2-2.3.8 (366.1KB)"1916time=2026-10-06T09:20:29.501Z level=INFO msg="Uploading hx9wvdx2l59iahwf9nmrx7rwkm6cymgs-glibc-2.44-25 (44.8MB)"1917time=2026-10-06T09:20:29.502Z level=INFO msg="Uploading vr887zd4l0370dnc4hkmjy817sgpdv05-niks3-1.13.0 (7.2MB)"1918time=2026-10-06T09:20:30.336Z level=INFO msg="Uploading 8 narinfos"1919time=2026-10-06T09:20:30.382Z level=INFO msg="Upload complete. (972ms)"1920