tribuchet: building on eliza Machine state will be reset. To keep it, pass --keep-machine-state start all VLans (finished: start all VLans, in 0.00 seconds) Test will time out and terminate in 3600.0 seconds run the VM test script machine: waiting for unit k3s.service machine: waiting for the VM to finish booting machine: starting vm machine: QEMU running (pid 45) machine # Disk image does not exist, creating the virtualisation disk image... machine # Formatting '/build/vm-state-machine/tmp.bt2gwhqAYO', fmt=raw size=8589934592 machine # mke2fs 1.47.4 (6-Mar-2025) machine # Discarding device blocks: 0/2097152 done machine # Creating filesystem with 2097152 4k blocks and 524288 inodes machine # Filesystem UUID: dc6dcea9-ca20-4e44-b262-97e5744b6dd6 machine # Superblock backups stored on blocks: machine # 32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632 machine # machine # Allocating group tables: 0/64 done machine # Writing inode tables: 0/64 done machine # Creating journal (16384 blocks): done machine # Writing superblocks and filesystem accounting information: 0/64 done machine # machine # Virtualisation disk image created. machine # Starting virtiofs daemons... machine # [2026-09-16T20:18:10Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1) machine # [2026-09-16T20:18:10Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether machine # [2026-09-16T20:18:10Z INFO virtiofsd] Waiting for vhost-user socket connection... machine # [2026-09-16T20:18:10Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1) machine # [2026-09-16T20:18:10Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether machine # [2026-09-16T20:18:10Z INFO virtiofsd] Waiting for vhost-user socket connection... machine # [2026-09-16T20:18:10Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1) machine # [2026-09-16T20:18:10Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether machine # [2026-09-16T20:18:10Z INFO virtiofsd] Waiting for vhost-user socket connection... machine # [2026-09-16T20:18:10Z INFO virtiofsd] Client connected, servicing requests machine # [2026-09-16T20:18:10Z INFO virtiofsd] Client connected, servicing requests machine # [2026-09-16T20:18:10Z INFO virtiofsd] Client connected, servicing requests machine # [ 0.000000] Booting Linux on physical CPU 0x0000000000 [0xc00fac40] machine # [ 0.000000] Linux version 6.18.51 (nixbld@localhost) (gcc (GCC) 15.3.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT Fri Sep 11 09:49:46 UTC 2026 machine # [ 0.000000] KASLR enabled machine # [ 0.000000] random: crng init done machine # [ 0.000000] Machine model: linux,dummy-virt machine # [ 0.000000] efi: UEFI not found. machine # [ 0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT machine # [ 0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000ffffffff] machine # [ 0.000000] NODE_DATA(0) allocated [mem 0xffdec0c0-0xffdef83f] machine # [ 0.000000] Zone ranges: machine # [ 0.000000] DMA [mem 0x0000000040000000-0x00000000ffffffff] machine # [ 0.000000] DMA32 empty machine # [ 0.000000] Normal empty machine # [ 0.000000] Device empty machine # [ 0.000000] Movable zone start for each node machine # [ 0.000000] Early memory node ranges machine # [ 0.000000] node 0: [mem 0x0000000040000000-0x00000000ffffffff] machine # [ 0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000ffffffff] machine # [ 0.000000] cma: Reserved 32 MiB at 0x00000000fac00000 machine # [ 0.000000] psci: probing for conduit method from DT. machine # [ 0.000000] psci: PSCIv1.3 detected in firmware. machine # [ 0.000000] psci: Using standard PSCI v0.2 function IDs machine # [ 0.000000] psci: Trusted OS migration not required machine # [ 0.000000] psci: SMC Calling Convention v1.1 machine # [ 0.000000] smccc: KVM: hypervisor services detected (0x00000000 0x00000000 0x00000000 0x00000003) machine # [ 0.000000] percpu: Embedded 76 pages/cpu s186648 r8192 d116456 u311296 machine # [ 0.000000] Detected PIPT I-cache on CPU0 machine # [ 0.000000] CPU features: detected: Address authentication (architected QARMA5 algorithm) machine # [ 0.000000] CPU features: detected: GICv3 CPU interface machine # [ 0.000000] CPU features: detected: Spectre-v4 machine # [ 0.000000] CPU features: detected: Spectre-BHB machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC03_CPU_38 machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC04_CPU_23 machine # [ 0.000000] alternatives: applying boot alternatives machine # [ 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/5svrkbkkf61yk0a6c0cmgvcyq80izwz6-nixos-system-machine-test/init regInfo=/nix/store/rbmxa8mrf9v4ha6sk0bkir3r29wnxvmg-closure-info/registration console=ttyAMA0,115200n8 console=tty0 machine # [ 0.000000] Unknown kernel command line parameters "regInfo=/nix/store/rbmxa8mrf9v4ha6sk0bkir3r29wnxvmg-closure-info/registration", will be passed to user space. machine # [ 0.000000] printk: log buffer data + meta data: 131072 + 458752 = 589824 bytes machine # [ 0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear) machine # [ 0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear) machine # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size adjusted to 3MB machine # [ 0.000000] software IO TLB: area num 2. machine # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size roundup to 4MB machine # [ 0.000000] software IO TLB: mapped [mem 0x00000000fa200000-0x00000000fa600000] (4MB) machine # [ 0.000000] Fallback order for Node 0: 0 machine # [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 786432 machine # [ 0.000000] Policy zone: DMA machine # [ 0.000000] mem auto-init: stack:all(zero), heap alloc:on, heap free:off machine # [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1 machine # [ 0.000000] allocated 6291456 bytes of page_ext machine # [ 0.000000] ftrace: allocating 74894 entries in 294 pages machine # [ 0.000000] ftrace: allocated 294 pages with 4 groups machine # [ 0.000000] rcu: Hierarchical RCU implementation. machine # [ 0.000000] rcu: RCU event tracing is enabled. machine # [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=2. machine # [ 0.000000] Trampoline variant of Tasks RCU enabled. machine # [ 0.000000] Rude variant of Tasks RCU enabled. machine # [ 0.000000] Tracing variant of Tasks RCU enabled. machine # [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. machine # [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2 machine # [ 0.000000] RCU Tasks: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2. machine # [ 0.000000] RCU Tasks Rude: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2. machine # [ 0.000000] RCU Tasks Trace: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2. machine # [ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0 machine # [ 0.000000] GICv3: 256 SPIs implemented machine # [ 0.000000] GICv3: 0 Extended SPIs implemented machine # [ 0.000000] Root IRQ handler: gic_handle_irq machine # [ 0.000000] GICv3: GICv3 features: 16 PPIs, DirectLPI machine # [ 0.000000] GICv3: GICD_CTLR.DS=1, SCR_EL3.FIQ=0 machine # [ 0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a0000 machine # [ 0.000000] ITS [mem 0x08080000-0x0809ffff] machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Devices @45100000 (indirect, esz 8, psz 64K, shr 1) machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @45110000 (flat, esz 8, psz 64K, shr 1) machine # [ 0.000000] GICv3: using LPI property table @0x0000000045120000 machine # [ 0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000045130000 machine # [ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention. machine # [ 0.000000] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns machine # [ 0.000000] arch_timer: cp15 timer running at 1000.00MHz (virt). machine # [ 0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns machine # [ 0.000000] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns machine # [ 0.000031] arm-pv: using stolen time PV machine # [ 0.000394] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____) machine # [ 0.000555] Console: colour dummy device 80x25 machine # [ 0.000563] printk: legacy console [tty0] enabled machine # [ 0.000762] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000) machine # [ 0.000769] pid_max: default: 32768 minimum: 301 machine # [ 0.000839] LSM: initializing lsm=capability,landlock,yama,bpf,ima machine # [ 0.000983] landlock: Up and running. machine # [ 0.000985] Yama: becoming mindful. machine # [ 0.001451] LSM support for eBPF active machine # [ 0.001625] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear) machine # [ 0.001688] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear) machine # [ 0.003181] cacheinfo: Unable to detect cache hierarchy for CPU 0 machine # [ 0.003928] rcu: Hierarchical SRCU implementation. machine # [ 0.003932] rcu: Max phase no-delay instances is 1000. machine # [ 0.004118] Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level machine # [ 0.005215] fsl-mc MSI: its@8080000 domain created machine # [ 0.005307] EFI services will not be available. machine # [ 0.005412] smp: Bringing up secondary CPUs ... machine # [ 0.006100] Detected PIPT I-cache on CPU1 machine # [ 0.006210] GICv3: CPU1: found redistributor 1 region 0:0x00000000080c0000 machine # [ 0.006344] GICv3: CPU1: using allocated LPI pending table @0x0000000045140000 machine # [ 0.006476] CPU1: Booted secondary processor 0x0000000001 [0xc00fac40] machine # [ 0.007073] smp: Brought up 1 node, 2 CPUs machine # [ 0.007086] SMP: Total of 2 processors activated. machine # [ 0.007089] CPU: All CPU(s) started at EL1 machine # [ 0.007098] CPU features: detected: Branch Target Identification machine # [ 0.007102] CPU features: detected: ARMv8.4 Translation Table Level machine # [ 0.007105] CPU features: detected: Instruction cache invalidation not required for I/D coherence machine # [ 0.007108] CPU features: detected: Data cache clean to the PoU not required for I/D coherence machine # [ 0.007112] CPU features: detected: Common not Private translations machine # [ 0.007115] CPU features: detected: CRC32 instructions machine # [ 0.007117] CPU features: detected: Data cache clean to Point of Deep Persistence machine # [ 0.007120] CPU features: detected: Data cache clean to Point of Persistence machine # [ 0.007123] CPU features: detected: Data independent timing control (DIT) machine # [ 0.007126] CPU features: detected: E0PD machine # [ 0.007129] CPU features: detected: Enhanced Counter Virtualization machine # [ 0.007132] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF) machine # [ 0.007135] CPU features: detected: Enhanced Virtualization Traps machine # [ 0.007138] CPU features: detected: Fine Grained Traps machine # [ 0.007141] CPU features: detected: Generic authentication (architected QARMA5 algorithm) machine # [ 0.007144] CPU features: detected: RCpc load-acquire (LDAPR) machine # [ 0.007147] CPU features: detected: LSE atomic instructions machine # [ 0.007150] CPU features: detected: Privileged Access Never machine # [ 0.007152] CPU features: detected: PMUv3 machine # [ 0.007155] CPU features: detected: RAS Extension Support machine # [ 0.007157] CPU features: detected: RASv1p1 Extension Support machine # [ 0.007160] CPU features: detected: Random Number Generator machine # [ 0.007162] CPU features: detected: Speculation barrier (SB) machine # [ 0.007165] CPU features: detected: Stage-2 Force Write-Back machine # [ 0.007167] CPU features: detected: TLB range maintenance instructions machine # [ 0.007171] CPU features: detected: Speculative Store Bypassing Safe (SSBS) machine # [ 0.007279] alternatives: applying system-wide alternatives machine # [ 0.010248] CPU features: detected: BBM Level 2 without TLB conflict abort machine # [ 0.010485] Memory: 2944568K/3145728K available (24448K kernel code, 7090K rwdata, 26360K rodata, 4736K init, 1107K bss, 154556K reserved, 32768K cma-reserved) machine # [ 0.011933] devtmpfs: initialized machine # [ 0.014569] posixtimers hash table entries: 1024 (order: 2, 16384 bytes, linear) machine # [ 0.014607] futex hash table entries: 512 (32768 bytes on 1 NUMA nodes, total 32 KiB, linear). machine # [ 0.014817] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL machine # [ 0.014822] 0 pages in range for non-PLT usage machine # [ 0.014823] 508288 pages in range for PLT usage machine # [ 0.014952] pinctrl core: initialized pinctrl subsystem machine # [ 0.015764] DMI not present or invalid. machine # [ 0.018994] NET: Registered PF_NETLINK/PF_ROUTE protocol family machine # [ 0.021504] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations machine # [ 0.021819] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations machine # [ 0.022152] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations machine # [ 0.022178] audit: initializing netlink subsys (disabled) machine # [ 0.023065] audit: type=2000 audit(0.020:1): state=initialized audit_enabled=0 res=1 machine # [ 0.025384] thermal_sys: Registered thermal governor 'fair_share' machine # [ 0.025395] thermal_sys: Registered thermal governor 'bang_bang' machine # [ 0.025410] thermal_sys: Registered thermal governor 'step_wise' machine # [ 0.025417] thermal_sys: Registered thermal governor 'user_space' machine # [ 0.025425] thermal_sys: Registered thermal governor 'power_allocator' machine # [ 0.025523] cpuidle: using governor ladder machine # [ 0.025576] cpuidle: using governor menu machine # [ 0.026390] hw-breakpoint: found 16 breakpoint and 4 watchpoint registers. machine # [ 0.026472] ASID allocator initialised with 65536 entries machine # [ 0.030015] Serial: AMBA PL011 UART driver machine # [ 0.046619] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 13, base_baud = 0) is a PL011 rev1 machine # [ 0.047109] printk: console [ttyAMA0] enabled machine # [ 0.074607] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages machine # [ 0.074621] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page machine # [ 0.074625] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages machine # [ 0.074628] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page machine # [ 0.074632] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages machine # [ 0.074634] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page machine # [ 0.074638] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages machine # [ 0.074641] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page machine # [ 0.088386] fbcon: Taking over console machine # [ 0.088402] ACPI: Interpreter disabled. machine # [ 0.089415] iommu: Default domain type: Translated machine # [ 0.089421] iommu: DMA domain TLB invalidation policy: strict mode machine # [ 0.092431] SCSI subsystem initialized machine # [ 0.092699] usbcore: registered new interface driver usbfs machine # [ 0.092732] usbcore: registered new interface driver hub machine # [ 0.092750] usbcore: registered new device driver usb machine # [ 0.093040] pps_core: LinuxPPS API ver. 1 registered machine # [ 0.093043] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti machine # [ 0.093051] PTP clock support registered machine # [ 0.093089] EDAC MC: Ver: 3.0.0 machine # [ 0.093286] scmi_core: SCMI protocol bus registered machine # [ 0.094935] FPGA manager framework machine # [ 0.095670] vgaarb: loaded machine # [ 0.104992] clocksource: Switched to clocksource arch_sys_counter machine # [ 0.105866] VFS: Disk quotas dquot_6.6.0 machine # [ 0.105896] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) machine # [ 0.111147] netfs: FS-Cache loaded machine # [ 0.111312] pnp: PnP ACPI: disabled machine # [ 0.115210] NET: Registered PF_INET protocol family machine # [ 0.115816] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear) machine # [ 0.146413] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear) machine # [ 0.146456] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear) machine # [ 0.146487] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear) machine # [ 0.146619] TCP bind hash table entries: 32768 (order: 8, 1048576 bytes, linear) machine # [ 0.146902] TCP: Hash tables configured (established 32768 bind 32768) machine # [ 0.147000] MPTCP token hash table entries: 4096 (order: 5, 98304 bytes, linear) machine # [ 0.147038] UDP hash table entries: 2048 (order: 5, 131072 bytes, linear) machine # [ 0.147096] UDP-Lite hash table entries: 2048 (order: 5, 131072 bytes, linear) machine # [ 0.147212] NET: Registered PF_UNIX/PF_LOCAL protocol family machine # [ 0.147228] NET: Registered PF_XDP protocol family machine # [ 0.147243] PCI: CLS 0 bytes, default 64 machine # [ 0.147517] Trying to unpack rootfs image as initramfs... machine # [ 0.161077] kvm [1]: HYP mode not available machine # [ 0.243229] Initialise system trusted keyrings machine # [ 0.245080] workingset: timestamp_bits=42 max_order=20 bucket_order=0 machine # [ 0.246505] squashfs: version 4.0 (2009/01/31) Phillip Lougher machine # [ 0.247317] 9p: Installing v9fs 9p2000 file system support machine # [ 0.260062] Key type asymmetric registered machine # [ 0.260074] Asymmetric key parser 'x509' registered machine # [ 0.260161] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 242) machine # [ 0.265302] io scheduler mq-deadline registered machine # [ 0.265336] io scheduler kyber registered machine # [ 0.277211] pl061_gpio 9030000.pl061: PL061 GPIO chip registered machine # [ 0.281083] ledtrig-cpu: registered to indicate activity on CPUs machine # [ 0.281562] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges: machine # [ 0.281585] pci-host-generic 4010000000.pcie: IO 0x003eff0000..0x003effffff -> 0x0000000000 machine # [ 0.281598] pci-host-generic 4010000000.pcie: MEM 0x0010000000..0x003efeffff -> 0x0010000000 machine # [ 0.281607] pci-host-generic 4010000000.pcie: MEM 0x8000000000..0xffffffffff -> 0x8000000000 machine # [ 0.281629] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits machine # [ 0.281655] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff] machine # [ 0.281747] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00 machine # [ 0.281758] pci_bus 0000:00: root bus resource [bus 00-ff] machine # [ 0.281764] pci_bus 0000:00: root bus resource [io 0x0000-0xffff] machine # [ 0.281769] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff] machine # [ 0.281774] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff] machine # [ 0.281840] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint machine # [ 0.282306] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint machine # [ 0.282498] pci 0000:00:01.0: BAR 0 [io 0x0000-0x001f] machine # [ 0.282516] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.282547] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.282563] pci 0000:00:01.0: ROM [mem 0x00000000-0x0003ffff pref] machine # [ 0.283023] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint machine # [ 0.283212] pci 0000:00:02.0: BAR 0 [io 0x0000-0x001f] machine # [ 0.283229] pci 0000:00:02.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.283259] pci 0000:00:02.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.283732] pci 0000:00:03.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint machine # [ 0.283919] pci 0000:00:03.0: BAR 0 [io 0x0000-0x007f] machine # [ 0.283939] pci 0000:00:03.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.283969] pci 0000:00:03.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.284419] pci 0000:00:04.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint machine # [ 0.284609] pci 0000:00:04.0: BAR 0 [io 0x0000-0x001f] machine # [ 0.284625] pci 0000:00:04.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.284655] pci 0000:00:04.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.284672] pci 0000:00:04.0: ROM [mem 0x00000000-0x0003ffff pref] machine # [ 0.311748] pci 0000:00:05.0: [1af4:1050] type 00 class 0x038000 conventional PCI endpoint machine # [ 0.311942] pci 0000:00:05.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.311972] pci 0000:00:05.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.312440] pci 0000:00:06.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint machine # [ 0.312626] pci 0000:00:06.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.312656] pci 0000:00:06.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.318435] pci 0000:00:07.0: [8086:24cd] type 00 class 0x0c0320 conventional PCI endpoint machine # [ 0.318621] pci 0000:00:07.0: BAR 0 [mem 0x00000000-0x00000fff] machine # [ 0.318902] pci 0000:00:08.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint machine # [ 0.319090] pci 0000:00:08.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.319120] pci 0000:00:08.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.319583] pci 0000:00:09.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint machine # [ 0.319768] pci 0000:00:09.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.319798] pci 0000:00:09.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.320249] pci 0000:00:0a.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint machine # [ 0.320435] pci 0000:00:0a.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.320464] pci 0000:00:0a.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.320909] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint machine # [ 0.331957] pci 0000:00:0b.0: BAR 0 [io 0x0000-0x003f] machine # [ 0.331980] pci 0000:00:0b.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.332010] pci 0000:00:0b.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.332476] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint machine # [ 0.332654] pci 0000:00:0c.0: BAR 0 [io 0x0000-0x001f] machine # [ 0.332670] pci 0000:00:0c.0: BAR 1 [mem 0x00000000-0x00000fff] machine # [ 0.332700] pci 0000:00:0c.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref] machine # [ 0.338914] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned machine # [ 0.338929] pci 0000:00:04.0: ROM [mem 0x10040000-0x1007ffff pref]: assigned machine # [ 0.338935] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned machine # [ 0.338978] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned machine # [ 0.339025] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned machine # [ 0.339072] pci 0000:00:04.0: BAR 4 [mem 0x800000c000-0x800000ffff 64bit pref]: assigned machine # [ 0.339118] pci 0000:00:05.0: BAR 4 [mem 0x8000010000-0x8000013fff 64bit pref]: assigned machine # [ 0.339165] pci 0000:00:06.0: BAR 4 [mem 0x8000014000-0x8000017fff 64bit pref]: assigned machine # [ 0.339210] pci 0000:00:08.0: BAR 4 [mem 0x8000018000-0x800001bfff 64bit pref]: assigned machine # [ 0.339256] pci 0000:00:09.0: BAR 4 [mem 0x800001c000-0x800001ffff 64bit pref]: assigned machine # [ 0.339301] pci 0000:00:0a.0: BAR 4 [mem 0x8000020000-0x8000023fff 64bit pref]: assigned machine # [ 0.339347] pci 0000:00:0b.0: BAR 4 [mem 0x8000024000-0x8000027fff 64bit pref]: assigned machine # [ 0.339429] pci 0000:00:0c.0: BAR 4 [mem 0x8000028000-0x800002bfff 64bit pref]: assigned machine # [ 0.339481] pci 0000:00:01.0: BAR 1 [mem 0x10080000-0x10080fff]: assigned machine # [ 0.339504] pci 0000:00:02.0: BAR 1 [mem 0x10081000-0x10081fff]: assigned machine # [ 0.339528] pci 0000:00:03.0: BAR 1 [mem 0x10082000-0x10082fff]: assigned machine # [ 0.339550] pci 0000:00:04.0: BAR 1 [mem 0x10083000-0x10083fff]: assigned machine # [ 0.339572] pci 0000:00:05.0: BAR 1 [mem 0x10084000-0x10084fff]: assigned machine # [ 0.339594] pci 0000:00:06.0: BAR 1 [mem 0x10085000-0x10085fff]: assigned machine # [ 0.339615] pci 0000:00:07.0: BAR 0 [mem 0x10086000-0x10086fff]: assigned machine # [ 0.339638] pci 0000:00:08.0: BAR 1 [mem 0x10087000-0x10087fff]: assigned machine # [ 0.339661] pci 0000:00:09.0: BAR 1 [mem 0x10088000-0x10088fff]: assigned machine # [ 0.339683] pci 0000:00:0a.0: BAR 1 [mem 0x10089000-0x10089fff]: assigned machine # [ 0.339705] pci 0000:00:0b.0: BAR 1 [mem 0x1008a000-0x1008afff]: assigned machine # [ 0.339727] pci 0000:00:0c.0: BAR 1 [mem 0x1008b000-0x1008bfff]: assigned machine # [ 0.339749] pci 0000:00:03.0: BAR 0 [io 0x1000-0x107f]: assigned machine # [ 0.339770] pci 0000:00:0b.0: BAR 0 [io 0x1080-0x10bf]: assigned machine # [ 0.339792] pci 0000:00:01.0: BAR 0 [io 0x10c0-0x10df]: assigned machine # [ 0.339813] pci 0000:00:02.0: BAR 0 [io 0x10e0-0x10ff]: assigned machine # [ 0.339835] pci 0000:00:04.0: BAR 0 [io 0x1100-0x111f]: assigned machine # [ 0.339857] pci 0000:00:0c.0: BAR 0 [io 0x1120-0x113f]: assigned machine # [ 0.339884] pci_bus 0000:00: resource 4 [io 0x0000-0xffff] machine # [ 0.339894] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff] machine # [ 0.339899] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff] machine # [ 0.340702] pci 0000:00:07.0: enabling device (0000 -> 0002) machine # [ 0.365209] pci 0000:00:07.0: quirk_usb_early_handoff+0x0/0xa60 took 23933 usecs machine # [ 0.382510] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003) machine # [ 0.384755] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003) machine # [ 0.388655] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003) machine # [ 0.391774] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003) machine # [ 0.397484] virtio-pci 0000:00:05.0: enabling device (0000 -> 0002) machine # [ 0.400045] virtio-pci 0000:00:06.0: enabling device (0000 -> 0002) machine # [ 0.403508] virtio-pci 0000:00:08.0: enabling device (0000 -> 0002) machine # [ 0.406277] virtio-pci 0000:00:09.0: enabling device (0000 -> 0002) machine # [ 0.410830] virtio-pci 0000:00:0a.0: enabling device (0000 -> 0002) machine # [ 0.414522] virtio-pci 0000:00:0b.0: enabling device (0000 -> 0003) machine # [ 0.417958] virtio-pci 0000:00:0c.0: enabling device (0000 -> 0003) machine # [ 0.424044] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled machine # [ 0.426770] msm_serial: driver initialized machine # [ 0.426945] SuperH (H)SCI(F) driver initialized machine # [ 0.426999] STM32 USART driver initialized machine # [ 0.448532] loop: module loaded machine # [ 0.448794] virtio_blk virtio2: 2/0/0 default/read/poll queues machine # [ 0.451301] virtio_blk virtio2: [vda] 16777216 512-byte logical blocks (8.59 GB/8.00 GiB) machine # [ 0.454563] megasas: 07.734.00.00-rc1 machine # [ 0.455348] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff] machine # [ 0.460288] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000 machine # [ 0.460332] Intel/Sharp Extended Query Table at 0x0031 machine # [ 0.464090] Using buffer write method machine # [ 0.464160] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff] machine # [ 0.467726] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000 machine # [ 0.467775] Intel/Sharp Extended Query Table at 0x0031 machine # [ 0.473630] Using buffer write method machine # [ 0.473675] Concatenating MTD devices: machine # [ 0.473679] (0): "0.flash" machine # [ 0.473684] (1): "0.flash" machine # [ 0.473688] into device "0.flash" machine # [ 0.607115] Freeing initrd memory: 26900K machine # [ 0.613750] tun: Universal TUN/TAP device driver, 1.6 machine # [ 0.617948] thunder_xcv, ver 1.0 machine # [ 0.618007] thunder_bgx, ver 1.0 machine # [ 0.618030] nicpf, ver 1.0 machine # [ 0.618570] e1000: Intel(R) PRO/1000 Network Driver machine # [ 0.618574] e1000: Copyright (c) 1999-2006 Intel Corporation. machine # [ 0.618596] e1000e: Intel(R) PRO/1000 Network Driver machine # [ 0.618602] e1000e: Copyright(c) 1999 - 2015 Intel Corporation. machine # [ 0.618630] igb: Intel(R) Gigabit Ethernet Network Driver machine # [ 0.618633] igb: Copyright (c) 2007-2014 Intel Corporation. machine # [ 0.618653] igbvf: Intel(R) Gigabit Virtual Function Network Driver machine # [ 0.618657] igbvf: Copyright (c) 2009 - 2012 Intel Corporation. machine # [ 0.618789] sky2: driver version 1.30 machine # [ 0.620352] usbcore: registered new interface driver usb-storage machine # [ 0.620446] usbcore: registered new interface driver usbserial_generic machine # [ 0.620463] usbserial: USB Serial support registered for generic machine # [ 0.621101] hv_vmbus: registering driver hyperv_keyboard machine # [ 0.622023] rtc-pl031 9010000.pl031: registered as rtc0 machine # [ 0.623029] rtc-pl031 9010000.pl031: setting system clock to 2026-09-16T20:18:11 UTC (1789589891) machine # [ 0.623095] ehci-pci 0000:00:07.0: EHCI Host Controller machine # [ 0.623176] ehci-pci 0000:00:07.0: new USB bus registered, assigned bus number 1 machine # [ 0.623368] i2c_dev: i2c /dev entries driver machine # [ 0.623842] ehci-pci 0000:00:07.0: irq 16, io mem 0x10086000 machine # [ 0.626410] sdhci: Secure Digital Host Controller Interface driver machine # [ 0.626416] sdhci: Copyright(c) Pierre Ossman machine # [ 0.626674] Synopsys Designware Multimedia Card Interface Driver machine # [ 0.627057] sdhci-pltfm: SDHCI platform and OF driver helper machine # [ 0.628554] hid: raw HID events driver (C) Jiri Kosina machine # [ 0.628800] usbcore: registered new interface driver usbhid machine # [ 0.628803] usbhid: USB HID core driver machine # [ 0.634393] ehci-pci 0000:00:07.0: USB 2.0 started, EHCI 1.00 machine # [ 0.634689] hub 1-0:1.0: USB hub found machine # [ 0.634710] hub 1-0:1.0: 6 ports detected machine # [ 0.639015] hw perfevents: enabled with armv8_pmuv3 PMU driver, 11 (0,800003ff) counters available machine # [ 0.640567] drop_monitor: Initializing network drop monitor service machine # [ 0.640725] NET: Registered PF_INET6 protocol family machine # [ 0.645239] Segment Routing with IPv6 machine # [ 0.645253] In-situ OAM (IOAM) with IPv6 machine # [ 0.645282] NET: Registered PF_PACKET protocol family machine # [ 0.645971] 9pnet: Installing 9P2000 support machine # [ 0.646014] Key type dns_resolver registered machine # [ 0.651380] registered taskstats version 1 machine # [ 0.651524] Loading compiled-in X.509 certificates machine # [ 0.661358] Demotion targets for Node 0: null machine # [ 0.661503] Key type .fscrypt registered machine # [ 0.661506] Key type fscrypt-provisioning registered machine # [ 0.661602] ima: No TPM chip found, activating TPM-bypass! machine # [ 0.661619] ima: Allocated hash algorithm: sha1 machine # [ 0.661639] ima: No architecture policies found machine # [ 0.662224] input: gpio-keys as /devices/platform/gpio-keys/input/input0 machine # [ 0.695968] clk: Disabling unused clocks machine # [ 0.695987] PM: genpd: Disabling unused power domains machine # [ 0.699224] Freeing unused kernel memory: 4736K machine # [ 0.699442] Run /init as init process machine # [ 0.722797] systemd[1]: Successfully made /usr/ read-only. machine # [ 0.881246] usb 1-1: new high-speed USB device number 2 using ehci-pci machine # [ 1.033831] 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/input1 machine # [ 1.057432] systemd[1]: systemd 261.2 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) machine # [ 1.057509] systemd[1]: Detected virtualization qemu. machine # [ 1.057600] systemd[1]: Detected architecture arm64. machine # [ 1.057615] systemd[1]: Running in initrd. machine # [ 1.058572] systemd[1]: Initializing machine ID from random generator. machine # [ 1.058841] systemd[1]: Hostname set to . machine # [ 1.149040] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:07.0-1/input0 machine # [ 1.269092] usb 1-2: new high-speed USB device number 3 using ehci-pci machine # [ 1.326727] systemd[1]: bpf-restrict-fs: LSM BPF program attached machine # [ 1.402798] systemd[1]: Queued start job for default target Initrd Default Target. machine # [ 1.420037] systemd[1]: Created slice Slice /system/modprobe. machine # [ 1.420310] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. machine # [ 1.420344] systemd[1]: Expecting device /dev/disk/by-label/nixos... machine # [ 1.420371] systemd[1]: Reached target Path Units. machine # [ 1.420386] systemd[1]: Reached target Slice Units. machine # [ 1.420403] systemd[1]: Reached target Swaps. machine # [ 1.420418] systemd[1]: Reached target Timer Units. machine # [ 1.420594] systemd[1]: Listening on D-Bus System Message Bus Socket. machine # [ 1.420766] systemd[1]: Listening on Journal Socket (/dev/log). machine # [ 1.420983] systemd[1]: Listening on Journal Sockets. machine # [ 1.421259] systemd[1]: Listening on udev Control Socket. machine # [ 1.421350] systemd[1]: Listening on udev Kernel Socket. machine # [ 1.421375] systemd[1]: Reached target Socket Units. machine # [ 1.423218] systemd[1]: Starting Create List of Static Device Nodes... machine # [ 1.423300] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs machine # [ 1.433244] systemd[1]: Mounting Kernel Configuration File System... machine # [ 1.461560] systemd[1]: Starting Journal Service... machine # [ 1.469144] systemd[1]: Starting Load Kernel Modules... machine # [ 1.469233] 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/input2 machine # [ 1.469266] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 1.480778] systemd[1]: Starting Coldplug All udev Devices... machine # [ 1.484083] hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:07.0-2/input0 machine # [ 1.501217] systemd[1]: Finished Create List of Static Device Nodes. machine # [ 1.506174] systemd[1]: Mounted Kernel Configuration File System. machine # [ 1.507491] [drm] pci: virtio-gpu-pci detected at 0000:00:05.0 machine # [ 1.507825] [drm] features: -virgl +edid -resource_blob -host_visible machine # [ 1.507827] [drm] features: -context_init machine # [ 1.508671] [drm] number of scanouts: 1 machine # [ 1.508683] [drm] number of cap sets: 0 machine # [ 1.524090] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. machine # [ 1.529344] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev machine # [ 1.529842] virtio-pci 0000:00:05.0: [drm] Registered 1 planes with drm panic machine # [ 1.529856] [drm] Initialized virtio_gpu 0.1.0 for 0000:00:05.0 on minor 0 machine # [ 1.534588] systemd[1]: Starting Create Static Device Nodes in /dev gracefully... machine # [ 1.535865] systemd-journald[80]: Collecting audit messages is disabled. machine # [ 1.545262] Console: switching to colour frame buffer device 160x50 machine # [ 1.551783] virtio-pci 0000:00:05.0: [drm] fb0: virtio_gpudrmfb frame buffer device machine # [ 1.569321] systemd[1]: Finished Load Kernel Modules. machine # [ 1.571061] systemd[1]: Starting Apply Kernel Variables... machine # [ 1.610375] systemd[1]: Finished Create Static Device Nodes in /dev gracefully. machine # [ 1.613193] systemd[1]: Finished Apply Kernel Variables. machine # [ 1.615119] systemd[1]: Starting Create Static Device Nodes in /dev... machine # [ 1.640977] systemd-modules-load[81]: Using 2 probe threads machine # [ 1.642723] systemd-modules-load[81]: Module 'virtio_balloon' is built in machine # [ 1.648897] systemd[1]: Started Journal Service. machine # [ 1.645978] systemd-modules-load[81]: Module 'virtio_console' is built in machine # [ 1.657957] systemd-modules-load[81]: Inserted module 'dm_mod' machine # [ 1.659415] systemd-modules-load[81]: Module 'virtio_rng' is built in machine # [ 1.661726] systemd-modules-load[81]: Inserted module 'virtio_gpu' machine # [ 1.668934] systemd[1]: Finished Create Static Device Nodes in /dev. machine # [ 1.671329] systemd[1]: Reached target Preparation for Local File Systems. machine # [ 1.676402] systemd[1]: Reached target Local File Systems. machine # [ 1.678680] systemd[1]: Starting Create System Files and Directories... machine # [ 1.680405] systemd[1]: Starting Rule-based Manager for Device Events and Files... machine # [ 1.706371] systemd[1]: Finished Create System Files and Directories. machine # [ 1.722165] systemd-udevd[95]: Using default interface naming scheme 'v261'. machine # [ 1.735964] systemd[1]: Started Rule-based Manager for Device Events and Files. machine # [ 1.768111] systemd[1]: Starting Virtual Console Setup... machine # [ 1.811118] systemd-vconsole-setup[112]: Configuration of first virtual console was skipped, ignoring remaining ones. machine # [ 1.814702] systemd[1]: Finished Virtual Console Setup. machine # [ 2.236342] systemd[1]: Finished Coldplug All udev Devices. machine # [ 2.237377] systemd[1]: Reached target System Initialization. machine # [ 2.238190] systemd[1]: Reached target Basic System. machine # [ 2.437358] (udev-worker)[121]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name. machine # [ 2.440365] (udev-worker)[121]: Network interface NamePolicy= disabled on kernel command line. machine # [ 2.447376] (udev-worker)[107]: Network interface NamePolicy= disabled on kernel command line. machine # [ 2.463976] systemd[1]: Found device /dev/disk/by-label/nixos. machine # [ 2.465095] systemd[1]: Reached target Initrd Root Device. machine # [ 2.468234] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos... machine # [ 2.525245] systemd-fsck[130]: nixos: clean, 12/524288 files, 58513/2097152 blocks machine # [ 2.536975] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos. machine # [ 2.540163] systemd[1]: Mounting /sysroot... machine # [ 2.663440] EXT4-fs (vda): mounted filesystem dc6dcea9-ca20-4e44-b262-97e5744b6dd6 r/w with ordered data mode. Quota mode: none. machine # [ 2.662809] systemd[1]: Mounted /sysroot. machine # [ 2.668758] systemd[1]: Reached target Initrd Root File System. machine # [ 2.676431] systemd[1]: Mounting /sysroot/nix/.ro-store... machine # [ 2.679894] systemd[1]: Mounting /sysroot/nix/.rw-store... machine # [ 2.692741] systemd[1]: Mounting /sysroot/run... machine # [ 2.712712] systemd[1]: Mounting /sysroot/tmp/shared... machine # [ 2.737180] systemd[1]: Mounting /sysroot/tmp/xchg... machine # [ 2.740117] systemd[1]: Starting Mountpoints Configured in the Real Root... machine # [ 2.753701] fuse: init (API version 7.45) machine # [ 2.757759] virtiofs virtio6: discovered new tag: nix-store machine # [ 2.758767] virtiofs virtio6: virtio_fs_setup_dax: No cache capability machine # [ 2.763768] systemd[1]: Mounted /sysroot/run. machine # [ 2.769433] systemd[1]: Mounted /sysroot/nix/.rw-store. machine # [ 2.780652] virtiofs virtio7: discovered new tag: shared machine # [ 2.784155] virtiofs virtio7: virtio_fs_setup_dax: No cache capability machine # [ 2.788403] virtiofs virtio8: discovered new tag: xchg machine # [ 2.791658] virtiofs virtio8: virtio_fs_setup_dax: No cache capability machine # [ 2.818505] systemd[1]: Starting rw-sysroot-nix-store.service... machine # [ 2.822352] systemd-sysroot-fstab-check[144]: /sysroot should be mounted in the initrd, will request daemon-reload. machine # [ 2.828685] systemd[1]: Mounted /sysroot/nix/.ro-store. machine # [ 2.830243] systemd[1]: Mounted /sysroot/tmp/shared. machine # [ 2.832638] systemd[1]: Reload requested from client PID 144 ('systemd-sysroot') (unit initrd-parse-etc.service)... machine # [ 2.839326] systemd[1]: Reloading... machine # [ 2.944049] systemd[1]: Reloading finished in 122 ms. machine # [ 2.994577] systemd-sysroot-fstab-check[144]: Requesting initrd-fs.target/start/replace... machine # [ 2.998861] systemd[1]: Mounted /sysroot/tmp/xchg. machine # [ 3.000668] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully. machine # [ 3.001894] systemd[1]: Finished rw-sysroot-nix-store.service. machine # [ 3.003236] systemd-sysroot-fstab-check[144]: Requesting swap.target/start/replace... machine # [ 3.007700] systemd[1]: initrd-parse-etc.service: Deactivated successfully. machine # [ 3.009658] systemd[1]: Finished Mountpoints Configured in the Real Root. machine # [ 3.012378] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies. machine # [ 3.017249] systemd[1]: Starting rw-sysroot-nix-store.service... machine # [ 3.047545] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully. machine # [ 3.049548] systemd[1]: Finished rw-sysroot-nix-store.service. machine # [ 3.426400] (udev-worker)[101]: mtd0ro: Failed to find and pin callout binary "/nix/store/gnadg5slifq2r638xvz4pv6vrsdl9xkj-systemd-261.2/lib/udev/mtd_probe": No such file or directory machine # [ 3.431003] (udev-worker)[101]: 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 directory machine # [ 3.440671] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 3.442590] systemd[1]: Stopped Virtual Console Setup. machine # [ 3.444651] systemd[1]: Stopping Virtual Console Setup... machine # [ 3.449175] systemd[1]: Starting Virtual Console Setup... machine # [ 3.465194] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 3.466955] systemd[1]: Stopped Virtual Console Setup. machine # [ 3.469808] systemd[1]: Starting Virtual Console Setup... machine # [ 3.497114] systemd[1]: Mounting /sysroot/nix/store... machine # [ 3.498445] systemd-vconsole-setup[174]: Configuration of first virtual console was skipped, ignoring remaining ones. machine # [ 3.516998] systemd[1]: Finished Virtual Console Setup. machine # [ 3.519396] systemd[1]: sysroot-run-credentials-systemd\x2dvconsole\x2dsetup.service.mount: Deactivated successfully. machine # [ 3.538264] systemd[1]: Mounted /sysroot/nix/store. machine # [ 3.540534] systemd[1]: Reached target Initrd File Systems. machine # [ 3.541977] systemd[1]: Starting Find NixOS closure... machine # [ 3.548075] systemd[1]: Starting Create Volatile Files and Directories in the Real Root... machine # [ 3.575992] systemd[1]: Finished Create Volatile Files and Directories in the Real Root. machine # [ 3.589960] systemd[1]: Finished Find NixOS closure. machine # [ 3.591244] systemd[1]: Reached target Initrd Default Target. machine # [ 3.593826] systemd[1]: Starting Cleaning Up and Shutting Down Daemons... machine # [ 3.619922] systemd[1]: Stopped target Initrd Default Target. machine # [ 3.621321] systemd[1]: Stopped target Basic System. machine # [ 3.622281] systemd[1]: Stopped target Initrd Root Device. machine # [ 3.623220] systemd[1]: Stopped target Path Units. machine # [ 3.624329] systemd[1]: systemd-ask-password-console.path: Deactivated successfully. machine # [ 3.626240] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch. machine # [ 3.627525] systemd[1]: Stopped target Slice Units. machine # [ 3.628457] systemd[1]: Stopped target Socket Units. machine # [ 3.629329] systemd[1]: Stopped target System Initialization. machine # [ 3.630280] systemd[1]: Stopped target Swaps. machine # [ 3.631038] systemd[1]: Stopped target Timer Units. machine # [ 3.631871] systemd[1]: dbus.socket: Deactivated successfully. machine # [ 3.632909] systemd[1]: Closed D-Bus System Message Bus Socket. machine # [ 3.633850] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully. machine # [ 3.636471] systemd[1]: Stopped Find NixOS closure. machine # [ 3.637948] systemd[1]: Starting rw-sysroot-nix-store.service... machine # [ 3.639917] systemd[1]: systemd-sysctl.service: Deactivated successfully. machine # [ 3.641915] systemd[1]: Stopped Apply Kernel Variables. machine # [ 3.643491] systemd[1]: systemd-modules-load.service: Deactivated successfully. machine # [ 3.645261] systemd[1]: Stopped Load Kernel Modules. machine # [ 3.646093] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully. machine # [ 3.647538] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root. machine # [ 3.648877] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully. machine # [ 3.650068] systemd[1]: Stopped Create System Files and Directories. machine # [ 3.651157] systemd[1]: Stopped target Local File Systems. machine # [ 3.652154] systemd[1]: Stopped target Preparation for Local File Systems. machine # [ 3.656310] systemd[1]: systemd-udev-trigger.service: Deactivated successfully. machine # [ 3.657495] systemd[1]: Stopped Coldplug All udev Devices. machine # [ 3.658747] systemd[1]: Stopping Rule-based Manager for Device Events and Files... machine # [ 3.659908] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 3.661397] systemd[1]: Stopped Virtual Console Setup. machine # [ 3.662204] systemd[1]: initrd-cleanup.service: Deactivated successfully. machine # [ 3.663183] systemd[1]: Finished Cleaning Up and Shutting Down Daemons. machine # [ 3.670061] systemd[1]: systemd-udevd.service: Deactivated successfully. machine # [ 3.671274] systemd[1]: Stopped Rule-based Manager for Device Events and Files. machine # [ 3.672418] systemd[1]: systemd-udevd.service: Consumed 1.989s CPU time over 1.989s wall clock time, 29M memory peak. machine # [ 3.673859] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully. machine # [ 3.674908] systemd[1]: Finished rw-sysroot-nix-store.service. machine # [ 3.675767] systemd[1]: systemd-udevd-control.socket: Deactivated successfully. machine # [ 3.676959] systemd[1]: Closed udev Control Socket. machine # [ 3.677707] systemd[1]: Starting Cleanup udev Database... machine # [ 3.678497] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully. machine # [ 3.679580] systemd[1]: Stopped Create Static Device Nodes in /dev. machine # [ 3.680542] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully. machine # [ 3.681675] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully. machine # [ 3.682684] systemd[1]: kmod-static-nodes.service: Deactivated successfully. machine # [ 3.683663] systemd[1]: Stopped Create List of Static Device Nodes. machine # [ 3.743405] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully. machine # [ 3.745508] systemd[1]: Finished Cleanup udev Database. machine # [ 3.746348] systemd[1]: Reached target Switch Root. machine # [ 3.750442] systemd[1]: Starting NixOS Activation... machine # [ 3.876440] initrd-nixos-activation-start[198]: booting system configuration /nix/store/5svrkbkkf61yk0a6c0cmgvcyq80izwz6-nixos-system-machine-test machine # [ 3.921159] initrd-nixos-activation-start[198]: running activation script... machine # [ 4.255784] initrd-nixos-activation-start[221]: setting up /etc... machine # [ 4.420158] systemd[1]: initrd-nixos-activation.service: Deactivated successfully. machine # [ 4.421478] systemd[1]: Finished NixOS Activation. machine # [ 4.422993] systemd[1]: Starting Switch Root... machine # [ 4.454811] systemd[1]: Switching root. machine # [ 4.582684] systemd-journald[80]: Received SIGTERM from PID 1 (systemd). machine # [ 5.253774] systemd[1]: systemd 261.2 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) machine # [ 5.255182] systemd[1]: Detected virtualization qemu. machine # [ 5.255329] systemd[1]: Detected architecture arm64. machine # [ 5.255546] systemd[1]: Detected first boot. machine # [ 5.275650] systemd[1]: Initializing machine ID from random generator. machine # [ 5.513448] systemd[1]: bpf-restrict-fs: LSM BPF program attached machine # [ 5.680289] systemd[1]: Applying preset policy. machine # [ 5.942513] systemd[1]: Populated /etc with preset unit settings. machine # [ 6.272677] systemd[1]: initrd-switch-root.service: Deactivated successfully. machine # [ 6.273787] systemd[1]: Stopped initrd-switch-root.service. machine # [ 6.276335] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. machine # [ 6.279233] systemd[1]: Created slice Slice /system/getty. machine # [ 6.281543] systemd[1]: Created slice User and Session Slice. machine # [ 6.282256] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. machine # [ 6.283124] systemd[1]: Started Forward Password Requests to Wall Directory Watch. machine # [ 6.283894] systemd[1]: Expecting device /dev/hvc0... machine # [ 6.284714] systemd[1]: Expecting device /dev/ttyAMA0... machine # [ 6.285600] systemd[1]: Reached target Local Encrypted Volumes. machine # [ 6.286472] systemd[1]: Stopped target initrd-fs.target. machine # [ 6.287344] systemd[1]: Stopped target initrd-root-fs.target. machine # [ 6.288194] systemd[1]: Stopped target initrd-switch-root.target. machine # [ 6.289052] systemd[1]: Reached target Virtual Machines and Containers. machine # [ 6.289912] systemd[1]: Reached target Path Units. machine # [ 6.290730] systemd[1]: Reached target Remote File Systems. machine # [ 6.291548] systemd[1]: Reached target Slice Units. machine # [ 6.292377] systemd[1]: Reached target Swaps. machine # [ 6.295151] systemd[1]: Listening on Query the User Interactively for a Password. machine # [ 6.299760] systemd[1]: Listening on Process Core Dump Socket. machine # [ 6.301899] systemd[1]: Listening on Credential Encryption/Decryption. machine # [ 6.304008] systemd[1]: Listening on Factory Reset Management. machine # [ 6.304696] systemd[1]: Listening on Hostname Service Socket. machine # [ 6.310582] systemd[1]: Starting Journal Log Access Socket... machine # [ 6.311943] systemd[1]: Listening on Journal Audit Socket. machine # [ 6.314371] systemd[1]: Listening on Console Output Muting Service Socket. machine # [ 6.315163] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket. machine # [ 6.315745] systemd[1]: TPM PCR Measurements skipped, unmet condition check ConditionSecurity=measured-os machine # [ 6.316525] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki machine # [ 6.321128] systemd[1]: Listening on Disk Repartitioning Service Socket. machine # [ 6.321771] systemd[1]: Listening on udev Control Socket. machine # [ 6.322637] systemd[1]: Listening on udev Varlink Socket. machine # [ 6.335848] systemd[1]: Mounting Huge Pages File System... machine # [ 6.348378] systemd[1]: Mounting POSIX Message Queue File System... machine # [ 6.359586] systemd[1]: Mounting Kernel Debug File System... machine # [ 6.369273] systemd[1]: Mounting Kernel Trace File System... machine # [ 6.376112] systemd[1]: Starting Create List of Static Device Nodes... machine # [ 6.378646] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs machine # [ 6.389706] systemd[1]: Mounting Kernel Configuration File System... machine # [ 6.390084] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm machine # [ 6.390347] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore machine # [ 6.390606] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse machine # [ 6.402504] systemd[1]: Mounting FUSE Control File System... machine # [ 6.402922] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67 machine # [ 6.422091] systemd[1]: Starting Journal Service... machine # [ 6.439700] systemd[1]: Starting Load Kernel Modules... machine # [ 6.451690] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer... machine # [ 6.465265] systemd[1]: Starting Remount Root and Kernel File Systems... machine # [ 6.465659] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 6.472086] systemd[1]: Starting Coldplug All udev Devices... machine # [ 6.475997] systemd[1]: Listening on Journal Log Access Socket. machine # [ 6.477516] systemd[1]: Mounted Huge Pages File System. machine # [ 6.480567] systemd[1]: Mounted POSIX Message Queue File System. machine # [ 6.483458] systemd[1]: Mounted Kernel Debug File System. machine # [ 6.485366] systemd[1]: Mounted Kernel Trace File System. machine # [ 6.488833] systemd[1]: Finished Create List of Static Device Nodes. machine # [ 6.491002] systemd[1]: Mounted Kernel Configuration File System. machine # [ 6.492741] systemd-journald[291]: Collecting audit messages is enabled. machine # [ 6.495968] systemd[1]: Mounted FUSE Control File System. machine # [ 6.501417] systemd[1]: Starting Create Static Device Nodes in /dev gracefully... machine # [ 6.504531] systemd[1]: Started Journal Service. machine # [ 6.500786] systemd[1]: Queued start job for default target Multi-User System. machine # [ 6.505138] systemd[1]: systemd-journald.service: Deactivated successfully. machine # [ 6.514440] systemd-modules-load[293]: Using 2 probe threads machine # [ 6.535660] systemd-modules-load[293]: Module 'atkbd' is built in machine # [ 6.537462] systemd-modules-load[293]: Module 'loop' is built in machine # [ 6.544083] systemd[1]: Finished Load Kernel Modules. machine # [ 6.549434] systemd[1]: Starting Apply Kernel Variables... machine # [ 6.577443] systemd-oomd[294]: No swap; memory pressure usage will be degraded machine # [ 6.585914] EXT4-fs (vda): re-mounted dc6dcea9-ca20-4e44-b262-97e5744b6dd6. machine # [ 6.588529] systemd[1]: Finished Remount Root and Kernel File Systems. machine # [ 6.590249] systemd[1]: Listening on Disk Image Download Service Socket. machine # [ 6.597390] systemd[1]: Starting Flush Journal to Persistent Storage... machine # [ 6.598520] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore machine # [ 6.609291] systemd[1]: Starting Load/Save OS Random Seed... machine # [ 6.612197] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 6.614961] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer. machine # [ 6.633908] systemd[1]: Finished Apply Kernel Variables. machine # [ 6.645843] systemd[1]: Finished Create Static Device Nodes in /dev gracefully. machine # [ 6.649222] systemd[1]: Starting Create Static Device Nodes in /dev... machine # [ 6.667324] systemd-journald[291]: Received client request to flush runtime journal. machine # [ 6.684534] systemd[1]: Finished Load/Save OS Random Seed. machine # [ 6.686886] systemd[1]: Reached target First Boot Complete. machine # [ 6.687982] systemd[1]: Finished Flush Journal to Persistent Storage. machine # [ 6.712157] systemd[1]: Finished Create Static Device Nodes in /dev. machine # [ 6.713152] systemd[1]: Reached target Preparation for Local File Systems. machine # [ 6.715099] systemd[1]: Starting Rule-based Manager for Device Events and Files... machine # [ 6.771674] systemd-udevd[321]: Using default interface naming scheme 'v261'. machine # [ 6.806774] systemd[1]: Started Rule-based Manager for Device Events and Files. machine # [ 7.147129] systemd[1]: Finished Coldplug All udev Devices. machine # [ 7.243904] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs machine # [ 7.257279] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse machine # [ 7.271066] systemd[1]: Mounting /run/wrappers... machine # [ 7.316135] systemd[1]: Mounted /run/wrappers. machine # [ 7.318146] systemd[1]: Reached target Local File Systems. machine # [ 7.322862] systemd[1]: Listening on Boot Loader Control Service Socket. machine # [ 7.326922] systemd[1]: Starting register-nix-paths.service... machine # [ 7.331287] systemd[1]: Starting Create SUID/SGID Wrappers... machine # [ 7.334841] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met. machine # [ 7.340646] systemd[1]: Starting Save Transient machine-id to Disk... machine # [ 7.343096] systemd[1]: Starting Create System Files and Directories... machine # [ 7.379984] systemd[1]: Condition check resulted in /dev/hvc0 being skipped. machine # [ 7.404931] systemd[1]: etc-machine\x2did.mount: Deactivated successfully. machine # [ 7.410834] systemd[1]: Finished Save Transient machine-id to Disk. machine # [ 7.451155] systemd[1]: Finished Create System Files and Directories. machine # [ 7.455001] systemd[1]: Starting Rebuild Journal Catalog... machine # [ 7.460208] systemd[1]: Starting Record System Boot/Shutdown in UTMP... machine # [ 7.505275] systemd[1]: Condition check resulted in /dev/ttyAMA0 being skipped. machine # [ 7.536614] systemd[1]: Finished Record System Boot/Shutdown in UTMP. machine # [ 7.547515] systemd[1]: Finished Rebuild Journal Catalog. machine # [ 7.551985] systemd[1]: Starting Update is Completed... machine # [ 7.590044] systemd[1]: Finished Update is Completed. machine # [ 7.591792] (udev-worker)[339]: Network interface NamePolicy= disabled on kernel command line. machine # [ 7.603911] (udev-worker)[324]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name. machine # [ 7.607368] (udev-worker)[324]: Network interface NamePolicy= disabled on kernel command line. machine # [ 7.638647] systemd[1]: Condition check resulted in Virtio network device being skipped. machine # [ 7.640768] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore machine # [ 7.642934] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met. machine # [ 7.644957] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67 machine # [ 7.648115] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore machine # [ 7.651316] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 7.653347] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 7.797964] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully. machine # [ 7.801875] systemd[1]: Finished Create SUID/SGID Wrappers. machine # [ 7.851156] mousedev: PS/2 mouse device common for all mice machine # [ 7.862280] systemd[1]: Finished register-nix-paths.service. machine # [ 7.865894] systemd[1]: Reached target System Initialization. machine # [ 7.866911] systemd[1]: Started Discard unused filesystem blocks once a week. machine # [ 7.867899] systemd[1]: Started Daily Cleanup of Temporary Directories. machine # [ 7.869022] systemd[1]: Reached target Timer Units. machine # [ 7.869768] systemd[1]: Listening on D-Bus System Message Bus Socket. machine # [ 7.871367] systemd[1]: Listening on Nix Daemon Socket. machine # [ 7.872911] systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. machine # [ 7.876495] systemd[1]: Reached target Socket Units. machine # [ 7.877314] systemd[1]: Reached target Basic System. machine # [ 7.880244] systemd[1]: Started backdoor.service. machine # [ 7.881095] systemd[1]: Starting Import lastlog data into lastlog2 database... machine # [ 7.883567] systemd[1]: Starting Name Service Cache Daemon (nsncd)... machine # [ 7.901515] systemd[1]: Starting Post-Boot Actions... machine # [ 7.907766] systemd[1]: Started Reset console on configuration changes. machine # [ 7.917891] systemd[1]: Starting resolvconf update... machine # [ 7.937431] systemd[1]: Started rustfs.service. machine # [ 7.951597] systemd[1]: Starting rustfs-setup.service... machine # [ 7.962579] systemd[1]: Starting D-Bus System Message Bus... machine # [ 7.971852] systemd[1]: Finished Post-Boot Actions. machine # connecting to host... machine # [ 8.025287] nsncd[426]: Sep 16 20:18:18.906 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" machine # [ 8.037548] systemd[1]: Started Name Service Cache Daemon (nsncd). machine # [ 8.038525] systemd[1]: Reached target Host and Network Name Lookups. machine # [ 8.048425] systemd[1]: Reached target User and Group Name Lookups. machine # [ 8.053928] systemd[1]: Starting User Login Management... machine: Guest shell says: b'Spawning backdoor root shell...\n' machine: connected to guest root shell machine # [ 8.117446] systemd[1]: Finished Import lastlog data into lastlog2 database. machine: (connecting took 8.45 seconds) machine: (finished: waiting for the VM to finish booting, in 9.24 seconds) machine # [ 8.148646] dbus-broker-launch[433]: Looking up NSS user entry for 'systemd-timesync'... machine # [ 8.164742] dbus-broker-launch[433]: NSS returned no entry for 'systemd-timesync' machine # [ 8.165935] dbus-broker-launch[433]: Invalid user-name in /nix/store/1pvby1g0vvnnf11w8l8hnqdrpyy2gwvg-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" machine # [ 8.184882] systemd[1]: Started D-Bus System Message Bus. machine # [ 8.222400] dbus-broker-launch[433]: Ready machine # [ 8.248520] systemd-logind[456]: Watching system buttons on /dev/input/event1 (QEMU QEMU USB Keyboard) machine # [ 8.253591] systemd-logind[456]: Watching system buttons on /dev/input/event0 (gpio-keys) machine # [ 8.459158] systemd[1]: Stopped target Host and Network Name Lookups. machine # [ 8.741487] systemd[1]: Stopping Host and Network Name Lookups... machine # [ 8.895021] nsncd[533]: Sep 16 20:18:19.299 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" machine # [ 8.900700] dhcpcd[577]: dhcpcd-10.3.2 starting machine # [ 8.901542] systemd[1]: Stopped target User and Group Name Lookups. machine # [ 8.902999] network-addresses-eth1-start[558]: adding address 192.168.1.1/24... done machine # [ 8.904460] network-addresses-eth1-start[558]: adding address 2001:db8:1::1/64... done machine # [ 8.906784] dhcpcd[627]: dev: loaded udev machine # [ 8.908053] systemd[1]: Stopping User and Group Name Lookups... machine # [ 8.909221] systemd[1]: Stopping Name Service Cache Daemon (nsncd)... machine # [ 8.910547] systemd[1]: nscd.service: Deactivated successfully. machine # [ 8.911987] systemd[1]: Stopped Name Service Cache Daemon (nsncd). machine # [ 8.913683] systemd-logind[456]: New seat seat0. machine # [ 8.914858] systemd[1]: Starting Name Service Cache Daemon (nsncd)... machine # [ 8.916918] systemd[1]: Finished resolvconf update. machine # [ 8.918610] systemd[1]: Started Name Service Cache Daemon (nsncd). machine # [ 8.919676] systemd[1]: Reached target Preparation for Network. machine # [ 8.920760] systemd[1]: Reached target Host and Network Name Lookups. machine # [ 8.921657] systemd[1]: Reached target User and Group Name Lookups. machine # [ 8.922510] systemd[1]: Starting DHCP Client... machine # [ 8.923174] systemd[1]: Starting Address configuration of eth1... machine # [ 8.924496] systemd[1]: Starting Extra networking commands.... machine # [ 8.925440] systemd[1]: Finished Address configuration of eth1. machine # [ 8.926461] systemd[1]: Finished Extra networking commands.. machine # [ 8.928049] systemd[1]: Reached target Network. machine # [ 8.929713] systemd[1]: Starting PostgreSQL Server... machine # [ 8.931921] systemd[1]: Starting Permit User Sessions... machine # [ 8.933479] systemd[1]: Started User Login Management. machine # [ 8.985330] systemd[1]: Starting linger-users.service... machine # [ 8.986829] systemd[1]: Finished Permit User Sessions. machine # [ 9.008435] systemd[1]: Started Getty on tty1. machine # [ 9.010704] systemd[1]: Reached target Login Prompts. machine # [ 9.050201] systemd[1]: linger-users.service: Deactivated successfully. machine # [ 9.061782] systemd[1]: Finished linger-users.service. machine # [ 9.148162] 8021q: 802.1Q VLAN Support v1.8 machine # [ 9.148591] 8021q: adding VLAN 0 to HW filter on device eth1 machine # [ 9.194860] postgresql-pre-start[643]: The files belonging to this database system will be owned by user "postgres". machine # [ 9.198711] postgresql-pre-start[643]: This user must also own the server process. machine # [ 9.202137] postgresql-pre-start[643]: The database cluster will be initialized with locale "en_US.UTF-8". machine # [ 9.205064] postgresql-pre-start[643]: The default database encoding has accordingly been set to "UTF8". machine # [ 9.206300] postgresql-pre-start[643]: The default text search configuration will be set to "english". machine # [ 9.207529] postgresql-pre-start[643]: Data page checksums are enabled. machine # [ 9.209318] postgresql-pre-start[643]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok machine # [ 9.210599] postgresql-pre-start[643]: creating subdirectories ... ok machine # [ 9.211441] postgresql-pre-start[643]: selecting dynamic shared memory implementation ... posix machine # [ 9.288890] postgresql-pre-start[643]: selecting default "max_connections" ... 100 machine # [ 9.323004] cfg80211: Loading compiled-in X.509 certificates for regulatory database machine # [ 9.361480] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' machine # [ 9.361983] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' machine # [ 9.363591] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2 machine # [ 9.363922] cfg80211: failed to load regulatory.db machine # [ 9.416789] postgresql-pre-start[643]: selecting default "shared_buffers" ... 128MB machine # [ 9.449323] 8021q: adding VLAN 0 to HW filter on device eth0 machine # [ 9.446228] dhcpcd[627]: eth0: waiting for carrier machine # [ 9.447755] dhcpcd[627]: libudev: received NULL device machine # [ 9.453312] dhcpcd[627]: libudev: received NULL device machine # [ 9.454597] dhcpcd[627]: eth0: carrier acquired machine # [ 9.463131] dhcpcd[627]: DUID 00:01:00:01:32:3d:b6:0c:52:54:00:12:34:56 machine # [ 9.464137] dhcpcd[627]: eth0: IAID 00:12:34:56 machine # [ 9.464774] dhcpcd[627]: eth0: adding address fe80::5054:ff:fe12:3456 machine # [ 9.555893] input: QEMU Virtio Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:06.0/virtio5/input/input3 machine # [ 9.661743] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. machine # [ 9.667720] systemd[1]: Starting Virtual Console Setup... machine # [ 9.696248] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 9.699652] systemd[1]: Stopped Virtual Console Setup. machine # [ 9.703351] systemd[1]: Starting Virtual Console Setup... machine # [ 9.738886] systemd-logind[456]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard) machine # [ 9.861027] systemd-vconsole-setup[676]: Configuration of first virtual console was skipped, ignoring remaining ones. machine # [ 9.866701] systemd[1]: Finished Virtual Console Setup. machine # [ 10.251854] postgresql-pre-start[643]: selecting default time zone ... UTC machine # [ 10.257121] postgresql-pre-start[643]: creating configuration files ... ok machine # [ 10.484545] postgresql-pre-start[643]: running bootstrap script ... ok machine # [ 11.017531] dhcpcd[627]: eth0: soliciting a DHCP lease machine # [ 11.028991] dhcpcd[627]: eth0: offered 10.0.2.15 from 10.0.2.2 machine # [ 11.036591] postgresql-pre-start[643]: performing post-bootstrap initialization ... ok machine # [ 11.044460] dhcpcd[627]: eth0: probing address 10.0.2.15/24 machine # [ 11.218755] postgresql-pre-start[643]: syncing data to disk ... ok machine # [ 11.221654] postgresql-pre-start[643]: initdb: warning: enabling "trust" authentication for local connections machine # [ 11.225538] postgresql-pre-start[643]: 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. machine # [ 11.231572] postgresql-pre-start[643]: Success. You can now start the database server using: machine # [ 11.235117] postgresql-pre-start[643]: pg_ctl -D /var/lib/postgresql/18 -l logfile start machine # [ 11.437789] postgres[695]: [695] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit machine # [ 11.443889] postgres[695]: [695] LOG: listening on IPv4 address "0.0.0.0", port 5432 machine # [ 11.446664] postgres[695]: [695] LOG: listening on IPv6 address "::", port 5432 machine # [ 11.449011] postgres[695]: [695] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432" machine # [ 11.464587] postgres[704]: [704] LOG: database system was shut down at 2026-09-16 20:18:21 GMT machine # [ 11.475966] postgres[695]: [695] LOG: database system is ready to accept connections machine # [ 11.482422] systemd[1]: Started PostgreSQL Server. machine # [ 11.491883] systemd[1]: Starting PostgreSQL Setup Scripts... machine # [ 11.768133] postgresql-setup-start[724]: CREATE DATABASE machine # [ 11.807522] postgresql-setup-start[729]: CREATE ROLE machine # [ 11.826655] postgresql-setup-start[731]: ALTER DATABASE machine # [ 11.832896] systemd[1]: Finished PostgreSQL Setup Scripts. machine # [ 11.833797] systemd[1]: Reached target PostgreSQL. machine # [ 12.118539] dhcpcd[627]: eth0: soliciting an IPv6 router machine # [ 12.121303] dhcpcd[627]: eth0: Router Advertisement from fe80::2 machine # [ 12.123856] dhcpcd[627]: eth0: adding address fec0::5054:ff:fe12:3456/64 machine # [ 12.126714] dhcpcd[627]: eth0: adding route to fec0::/64 machine # [ 12.129085] dhcpcd[627]: eth0: adding default route via fe80::2 machine # [ 16.051568] rustfs-setup-start[768]: mb s3://niks3 machine # [ 16.066028] systemd[1]: Finished rustfs-setup.service. machine # [ 16.544771] dhcpcd[627]: eth0: leased 10.0.2.15 for 86400 seconds machine # [ 16.548225] dhcpcd[627]: eth0: adding route to 10.0.2.0/24 machine # [ 16.550829] dhcpcd[627]: eth0: adding default route via 10.0.2.2 machine # [ 16.772616] systemd[1]: Started DHCP Client. machine # [ 16.776940] systemd[1]: Reached target Network is Online. machine # [ 16.783032] systemd[1]: Starting k3s service... machine # [ 16.900962] k3s[841]: time="2026-09-16T20:18:27Z" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock" machine # [ 16.905534] k3s[841]: time="2026-09-16T20:18:27Z" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/12d1185026784ba3717903546b35f7d424a0c42f9bb75a7f03f0ead9f837718b" machine # [ 20.105388] k3s[841]: time="2026-09-16T20:18:30Z" level=info msg="Starting k3s 1.35.8+k3s1 (e952d68a)" machine # [ 20.134081] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Configuring sqlite3 database connection pooling: maxIdle=20, maxOpen=0, maxLifetime=0s, maxIdleTime=2m0s" machine # [ 20.141015] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Kine built with sqlite from github.com/mattn/go-sqlite3 version 3.53.3" machine # [ 20.146810] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Configuring database table schema and indexes, this may take a moment..." machine # [ 20.153001] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Database tables and indexes are up to date" machine # [ 20.157495] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Running startup VACUUM to reclaim disk space, this may take a moment..." machine # [ 20.164412] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Startup VACUUM completed successfully" machine # [ 20.166281] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Kine available at unix://kine.sock" machine # [ 20.168222] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]" machine # [ 20.174949] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="Datastore connection validated successfully, proceeding with bootstrap data generation" machine # [ 20.179787] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="generated self-signed CA certificate CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:31.05670752 +0000 UTC notAfter=2036-09-13 19:18:31.05670752 +0000 UTC" machine # [ 20.186811] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.193295] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=system:k3s-supervisor,O=system:masters signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.199704] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.205858] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.211132] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=system:apiserver,O=system:masters signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.216245] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.220808] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="generated self-signed CA certificate CN=k3s-server-ca@1789589911: notBefore=2026-09-16 19:18:31.06632024 +0000 UTC notAfter=2036-09-13 19:18:31.06632024 +0000 UTC" machine # [ 20.225162] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.228928] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=kube-scheduler signed by CN=k3s-server-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.232489] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=kube-controller-manager signed by CN=k3s-server-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.236172] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="generated self-signed CA certificate CN=k3s-request-header-ca@1789589911: notBefore=2026-09-16 19:18:31.07110776 +0000 UTC notAfter=2036-09-13 19:18:31.07110776 +0000 UTC" machine # [ 20.240064] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.243437] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="generated self-signed CA certificate CN=etcd-server-ca@1789589911: notBefore=2026-09-16 19:18:31.07312392 +0000 UTC notAfter=2036-09-13 19:18:31.07312392 +0000 UTC" machine # [ 20.247748] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.251483] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="generated self-signed CA certificate CN=etcd-peer-ca@1789589911: notBefore=2026-09-16 19:18:31.07508698 +0000 UTC notAfter=2036-09-13 19:18:31.07508698 +0000 UTC" machine # [ 20.255438] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.259007] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.310607] k3s[841]: time="2026-09-16T20:18:31Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1789589911: notBefore=2026-09-16 19:18:31 +0000 UTC notAfter=2027-09-16 19:18:31 +0000 UTC" machine # [ 20.314702] k3s[841]: time="2026-09-16T20:18:31Z" level=warning msg="dynamiclistener [::]:6443: no cached certificate available for preload - deferring certificate load until storage initialization or first client request" machine # [ 20.318439] k3s[841]: time="2026-09-16T20:18:31Z" 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__9a9d_43f9_43e1_fefd-72ee68:fec0::9a9d:43f9:43e1:fefd 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=E55BEF79FB284E110024603AC7D1958AC8FD8344]" machine # [ 22.470081] k3s[841]: time="2026-09-16T20:18:33Z" level=info msg="Password verified locally for node machine" machine # [ 22.474983] k3s[841]: time="2026-09-16T20:18:33Z" level=info msg="certificate CN=machine signed by CN=k3s-server-ca@1789589911: notBefore=2026-09-16 19:18:33 +0000 UTC notAfter=2027-09-16 19:18:33 +0000 UTC" machine # [ 22.872748] k3s[841]: time="2026-09-16T20:18:33Z" level=info msg="certificate CN=system:node:machine,O=system:nodes signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:33 +0000 UTC notAfter=2027-09-16 19:18:33 +0000 UTC" machine # [ 22.974081] k3s[841]: time="2026-09-16T20:18:33Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:33 +0000 UTC notAfter=2027-09-16 19:18:33 +0000 UTC" machine # [ 23.103107] k3s[841]: time="2026-09-16T20:18:33Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1789589911: notBefore=2026-09-16 19:18:33 +0000 UTC notAfter=2027-09-16 19:18:33 +0000 UTC" machine # [ 23.214709] k3s[841]: time="2026-09-16T20:18:34Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:45346: runtime core not ready" machine # [ 23.340579] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Module overlay was already loaded" machine # [ 23.431943] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this. machine # [ 23.440811] Bridge firewalling registered machine # [ 23.454532] k3s[841]: time="2026-09-16T20:18:34Z" level=warning msg="Failed to load kernel module iptable_nat with modprobe" machine # [ 23.463868] k3s[841]: time="2026-09-16T20:18:34Z" level=warning msg="Failed to load kernel module iptable_filter with modprobe" machine # [ 23.476814] k3s[841]: time="2026-09-16T20:18:34Z" level=warning msg="Failed to load kernel module nft-expr-counter with modprobe" machine # [ 23.552091] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Set sysctl 'net/ipv4/conf/all/forwarding' to 1" machine # [ 23.555334] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_max' to 131072" machine # [ 23.558511] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400" machine # [ 23.560356] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_close_wait' to 3600" machine # [ 23.565204] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Creating k3s-cert-monitor event broadcaster" machine # [ 23.568217] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Connecting to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 23.569723] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Saving cluster bootstrap data to datastore" machine # [ 23.574317] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]" machine # [ 23.577755] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Connection to etcd is ready" machine # [ 23.579533] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="ETCD server is now running" machine # [ 23.585813] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Polling for API server readiness: GET /readyz failed: the server is currently unable to handle the request" machine # [ 23.588534] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Handling backend connection request [machine]" machine # [ 23.597507] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 23.599164] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Remotedialer connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 23.608322] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log" machine # [ 23.610865] k3s[841]: time="2026-09-16T20:18:34Z" 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" machine # [ 23.637576] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml" machine # [ 23.640778] k3s[841]: time="2026-09-16T20:18:34Z" 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" machine # [ 23.651210] k3s[841]: time="2026-09-16T20:18:34Z" 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" machine # [ 23.687254] k3s[841]: time="2026-09-16T20:18:34Z" 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" machine # [ 23.700301] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token" machine # [ 23.702029] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="To join server node to cluster: k3s server -s https://10.0.2.15:6443 -t ${SERVER_NODE_TOKEN}" machine # [ 23.703935] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token" machine # [ 23.705739] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="To join agent node to cluster: k3s agent -s https://10.0.2.15:6443 -t ${AGENT_NODE_TOKEN}" machine # [ 23.707527] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml" machine # [ 23.712142] k3s[841]: time="2026-09-16T20:18:34Z" level=info msg="Run: k3s kubectl" machine # [ 23.713174] k3s[841]: I0916 20:18:34.504164 841 options.go:263] external host was not specified, using 10.0.2.15 machine # [ 23.714505] k3s[841]: I0916 20:18:34.509266 841 server.go:158] Version: v1.35.8+k3s1 machine # [ 23.715558] k3s[841]: I0916 20:18:34.509326 841 server.go:160] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 23.796097] k3s[841]: time="2026-09-16T20:18:34Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:45380: runtime core not ready" machine # [ 24.024106] k3s[841]: time="2026-09-16T20:18:34Z" 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" machine # [ 24.211751] k3s[841]: I0916 20:18:35.093495 841 shared_informer.go:349] "Waiting for caches to sync" controller="node_authorizer" machine # [ 24.218680] k3s[841]: I0916 20:18:35.100566 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 24.222647] k3s[841]: I0916 20:18:35.104511 841 plugins.go:157] Loaded 14 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,RuntimeClass,DefaultIngressClass,PodTopologyLabels,MutatingAdmissionPolicy,MutatingAdmissionWebhook. machine # [ 24.227402] k3s[841]: I0916 20:18:35.104578 841 plugins.go:160] Loaded 14 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,PodSecurity,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,ClusterTrustBundleAttest,CertificateSubjectRestriction,NodeDeclaredFeatureValidator,ValidatingAdmissionPolicy,ValidatingAdmissionWebhook,ResourceQuota. machine # [ 24.232348] k3s[841]: I0916 20:18:35.105160 841 instance.go:240] Using reconciler: lease machine # [ 24.241845] k3s[841]: I0916 20:18:35.123350 841 handler.go:304] Adding GroupVersion apiextensions.k8s.io v1 to ResourceManager machine # [ 24.243496] k3s[841]: W0916 20:18:35.123518 841 genericapiserver.go:787] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources. machine # [ 24.250001] k3s[841]: I0916 20:18:35.131856 841 cidrallocator.go:198] starting ServiceCIDR Allocator Controller machine # [ 24.309619] k3s[841]: I0916 20:18:35.191438 841 handler.go:304] Adding GroupVersion v1 to ResourceManager machine # [ 24.311201] k3s[841]: I0916 20:18:35.191859 841 apis.go:112] API group "internal.apiserver.k8s.io" is not enabled, skipping. machine # [ 24.354071] k3s[841]: I0916 20:18:35.235916 841 apis.go:112] API group "storagemigration.k8s.io" is not enabled, skipping. machine # [ 24.435537] k3s[841]: I0916 20:18:35.317305 841 handler.go:304] Adding GroupVersion authentication.k8s.io v1 to ResourceManager machine # [ 24.437379] k3s[841]: W0916 20:18:35.317416 841 genericapiserver.go:787] Skipping API authentication.k8s.io/v1beta1 because it has no resources. machine # [ 24.439019] k3s[841]: W0916 20:18:35.317431 841 genericapiserver.go:787] Skipping API authentication.k8s.io/v1alpha1 because it has no resources. machine # [ 24.440841] k3s[841]: I0916 20:18:35.319376 841 handler.go:304] Adding GroupVersion authorization.k8s.io v1 to ResourceManager machine # [ 24.442420] k3s[841]: W0916 20:18:35.319402 841 genericapiserver.go:787] Skipping API authorization.k8s.io/v1beta1 because it has no resources. machine # [ 24.444491] k3s[841]: I0916 20:18:35.320764 841 handler.go:304] Adding GroupVersion autoscaling v2 to ResourceManager machine # [ 24.445981] k3s[841]: I0916 20:18:35.322579 841 handler.go:304] Adding GroupVersion autoscaling v1 to ResourceManager machine # [ 24.447486] k3s[841]: W0916 20:18:35.322605 841 genericapiserver.go:787] Skipping API autoscaling/v2beta1 because it has no resources. machine # [ 24.449247] k3s[841]: W0916 20:18:35.322624 841 genericapiserver.go:787] Skipping API autoscaling/v2beta2 because it has no resources. machine # [ 24.450959] k3s[841]: I0916 20:18:35.325122 841 handler.go:304] Adding GroupVersion batch v1 to ResourceManager machine # [ 24.452387] k3s[841]: W0916 20:18:35.325148 841 genericapiserver.go:787] Skipping API batch/v1beta1 because it has no resources. machine # [ 24.453973] k3s[841]: I0916 20:18:35.326774 841 handler.go:304] Adding GroupVersion certificates.k8s.io v1 to ResourceManager machine # [ 24.455530] k3s[841]: W0916 20:18:35.326795 841 genericapiserver.go:787] Skipping API certificates.k8s.io/v1beta1 because it has no resources. machine # [ 24.457355] k3s[841]: W0916 20:18:35.326804 841 genericapiserver.go:787] Skipping API certificates.k8s.io/v1alpha1 because it has no resources. machine # [ 24.459138] k3s[841]: I0916 20:18:35.327795 841 handler.go:304] Adding GroupVersion coordination.k8s.io v1 to ResourceManager machine # [ 24.460732] k3s[841]: W0916 20:18:35.327815 841 genericapiserver.go:787] Skipping API coordination.k8s.io/v1beta1 because it has no resources. machine # [ 24.462431] k3s[841]: W0916 20:18:35.327826 841 genericapiserver.go:787] Skipping API coordination.k8s.io/v1alpha2 because it has no resources. machine # [ 24.464109] k3s[841]: I0916 20:18:35.328674 841 handler.go:304] Adding GroupVersion discovery.k8s.io v1 to ResourceManager machine # [ 24.465564] k3s[841]: W0916 20:18:35.328713 841 genericapiserver.go:787] Skipping API discovery.k8s.io/v1beta1 because it has no resources. machine # [ 24.467202] k3s[841]: I0916 20:18:35.332644 841 handler.go:304] Adding GroupVersion networking.k8s.io v1 to ResourceManager machine # [ 24.468786] k3s[841]: W0916 20:18:35.332674 841 genericapiserver.go:787] Skipping API networking.k8s.io/v1beta1 because it has no resources. machine # [ 24.470555] k3s[841]: I0916 20:18:35.333342 841 handler.go:304] Adding GroupVersion node.k8s.io v1 to ResourceManager machine # [ 24.472003] k3s[841]: W0916 20:18:35.333365 841 genericapiserver.go:787] Skipping API node.k8s.io/v1beta1 because it has no resources. machine # [ 24.473612] k3s[841]: W0916 20:18:35.333372 841 genericapiserver.go:787] Skipping API node.k8s.io/v1alpha1 because it has no resources. machine # [ 24.475346] k3s[841]: I0916 20:18:35.334598 841 handler.go:304] Adding GroupVersion policy v1 to ResourceManager machine # [ 24.477435] k3s[841]: W0916 20:18:35.334619 841 genericapiserver.go:787] Skipping API policy/v1beta1 because it has no resources. machine # [ 24.482436] k3s[841]: I0916 20:18:35.337255 841 handler.go:304] Adding GroupVersion rbac.authorization.k8s.io v1 to ResourceManager machine # [ 24.484186] k3s[841]: W0916 20:18:35.337285 841 genericapiserver.go:787] Skipping API rbac.authorization.k8s.io/v1beta1 because it has no resources. machine # [ 24.485974] k3s[841]: W0916 20:18:35.337295 841 genericapiserver.go:787] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources. machine # [ 24.487705] k3s[841]: I0916 20:18:35.337932 841 handler.go:304] Adding GroupVersion scheduling.k8s.io v1 to ResourceManager machine # [ 24.489496] k3s[841]: W0916 20:18:35.337958 841 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1beta1 because it has no resources. machine # [ 24.491254] k3s[841]: W0916 20:18:35.337967 841 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources. machine # [ 24.493032] k3s[841]: I0916 20:18:35.341551 841 handler.go:304] Adding GroupVersion storage.k8s.io v1 to ResourceManager machine # [ 24.494641] k3s[841]: W0916 20:18:35.341581 841 genericapiserver.go:787] Skipping API storage.k8s.io/v1beta1 because it has no resources. machine # [ 24.496311] k3s[841]: W0916 20:18:35.341592 841 genericapiserver.go:787] Skipping API storage.k8s.io/v1alpha1 because it has no resources. machine # [ 24.498214] k3s[841]: I0916 20:18:35.343228 841 handler.go:304] Adding GroupVersion flowcontrol.apiserver.k8s.io v1 to ResourceManager machine # [ 24.500939] k3s[841]: W0916 20:18:35.343253 841 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta3 because it has no resources. machine # [ 24.502639] k3s[841]: W0916 20:18:35.343270 841 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta2 because it has no resources. machine # [ 24.504388] k3s[841]: W0916 20:18:35.343276 841 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta1 because it has no resources. machine # [ 24.506241] k3s[841]: I0916 20:18:35.348959 841 handler.go:304] Adding GroupVersion apps v1 to ResourceManager machine # [ 24.507559] k3s[841]: W0916 20:18:35.348995 841 genericapiserver.go:787] Skipping API apps/v1beta2 because it has no resources. machine # [ 24.509155] k3s[841]: W0916 20:18:35.349009 841 genericapiserver.go:787] Skipping API apps/v1beta1 because it has no resources. machine # [ 24.510668] k3s[841]: I0916 20:18:35.351889 841 handler.go:304] Adding GroupVersion admissionregistration.k8s.io v1 to ResourceManager machine # [ 24.512281] k3s[841]: W0916 20:18:35.351916 841 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources. machine # [ 24.514034] k3s[841]: W0916 20:18:35.351925 841 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources. machine # [ 24.515837] k3s[841]: I0916 20:18:35.352811 841 handler.go:304] Adding GroupVersion events.k8s.io v1 to ResourceManager machine # [ 24.517373] k3s[841]: W0916 20:18:35.352833 841 genericapiserver.go:787] Skipping API events.k8s.io/v1beta1 because it has no resources. machine # [ 24.518961] k3s[841]: I0916 20:18:35.356380 841 handler.go:304] Adding GroupVersion resource.k8s.io v1 to ResourceManager machine # [ 24.520514] k3s[841]: W0916 20:18:35.356417 841 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta2 because it has no resources. machine # [ 24.522122] k3s[841]: W0916 20:18:35.356436 841 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta1 because it has no resources. machine # [ 24.523726] k3s[841]: W0916 20:18:35.356458 841 genericapiserver.go:787] Skipping API resource.k8s.io/v1alpha3 because it has no resources. machine # [ 24.525507] k3s[841]: I0916 20:18:35.361799 841 handler.go:304] Adding GroupVersion apiregistration.k8s.io v1 to ResourceManager machine # [ 24.527038] k3s[841]: W0916 20:18:35.361833 841 genericapiserver.go:787] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources. machine # [ 24.656727] k3s[841]: time="2026-09-16T20:18:35Z" level=info msg="containerd is now running" machine # [ 24.671287] k3s[841]: time="2026-09-16T20:18:35Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/k3s-airgap-images-arm64.tar.zst" machine # [ 25.461271] k3s[841]: I0916 20:18:36.343079 841 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt" machine # [ 25.463695] k3s[841]: I0916 20:18:36.343856 841 secure_serving.go:211] Serving securely on 127.0.0.1:6444 machine # [ 25.465783] k3s[841]: I0916 20:18:36.343934 841 tlsconfig.go:243] "Starting DynamicServingCertificateController" machine # [ 25.472172] k3s[841]: I0916 20:18:36.346299 841 customresource_discovery_controller.go:294] Starting DiscoveryController machine # [ 25.473676] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Starting legacy_token_tracking_controller" logger=k3s machine # [ 25.475051] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Waiting for caches to sync" logger=k3s machine # [ 25.476341] k3s[841]: I0916 20:18:36.346791 841 apf_controller.go:377] Starting API Priority and Fairness config controller machine # [ 25.478524] k3s[841]: I0916 20:18:36.347113 841 cluster_authentication_trust_controller.go:459] Starting cluster_authentication_trust_controller controller machine # [ 25.481842] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Waiting for caches to sync" logger=k3s machine # [ 25.483189] k3s[841]: I0916 20:18:36.348368 841 local_available_controller.go:156] Starting LocalAvailability controller machine # [ 25.488174] k3s[841]: I0916 20:18:36.348395 841 cache.go:32] Waiting for caches to sync for LocalAvailability controller machine # [ 25.489662] k3s[841]: I0916 20:18:36.348525 841 controller.go:113] "Deleting old lease on startup" lease="kube-system/apiserver-ik4pcwfs7qgdl76byc4pomgvia" machine # [ 25.491455] k3s[841]: I0916 20:18:36.349047 841 remote_available_controller.go:425] Starting RemoteAvailability controller machine # [ 25.496173] k3s[841]: I0916 20:18:36.349071 841 cache.go:32] Waiting for caches to sync for RemoteAvailability controller machine # [ 25.497676] k3s[841]: I0916 20:18:36.349135 841 apiservice_controller.go:100] Starting APIServiceRegistrationController machine # [ 25.499102] k3s[841]: I0916 20:18:36.349161 841 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller machine # [ 25.504214] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Starting apiserver lease garbage collector" logger=k3s machine # [ 25.505622] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Waiting for caches to sync" logger=k3s machine # [ 25.506838] k3s[841]: I0916 20:18:36.349588 841 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" machine # [ 25.509637] k3s[841]: I0916 20:18:36.350029 841 aggregator.go:185] waiting for initial CRD sync... machine # [ 25.510847] k3s[841]: I0916 20:18:36.350072 841 controller.go:78] Starting OpenAPI AggregationController machine # [ 25.513632] k3s[841]: I0916 20:18:36.350110 841 controller.go:80] Starting OpenAPI V3 AggregationController machine # [ 25.514981] k3s[841]: I0916 20:18:36.350605 841 system_namespaces_controller.go:66] Starting system namespaces controller machine # [ 25.520244] k3s[841]: I0916 20:18:36.343961 841 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" machine # [ 25.524182] k3s[841]: I0916 20:18:36.351276 841 controller.go:142] Starting OpenAPI controller machine # [ 25.525630] k3s[841]: I0916 20:18:36.351328 841 controller.go:90] Starting OpenAPI V3 controller machine # [ 25.527040] k3s[841]: I0916 20:18:36.351351 841 naming_controller.go:305] Starting NamingConditionController machine # [ 25.528596] k3s[841]: I0916 20:18:36.351447 841 nonstructuralschema_controller.go:202] Starting NonStructuralSchemaConditionController machine # [ 25.530310] k3s[841]: I0916 20:18:36.351493 841 apiapproval_controller.go:196] Starting KubernetesAPIApprovalPolicyConformantConditionController machine # [ 25.532282] k3s[841]: I0916 20:18:36.351517 841 crd_finalizer.go:273] Starting CRDFinalizer machine # [ 25.533502] k3s[841]: I0916 20:18:36.343977 841 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt" machine # [ 25.535528] k3s[841]: I0916 20:18:36.352240 841 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt" machine # [ 25.537726] k3s[841]: I0916 20:18:36.352549 841 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt" machine # [ 25.539837] k3s[841]: I0916 20:18:36.362890 841 default_servicecidr_controller.go:110] Starting kubernetes-service-cidr-controller machine # [ 25.541495] k3s[841]: I0916 20:18:36.362944 841 shared_informer.go:349] "Waiting for caches to sync" controller="kubernetes-service-cidr-controller" machine # [ 25.543191] k3s[841]: I0916 20:18:36.364221 841 crdregistration_controller.go:114] Starting crd-autoregister controller machine # [ 25.544842] k3s[841]: I0916 20:18:36.364263 841 shared_informer.go:349] "Waiting for caches to sync" controller="crd-autoregister" machine # [ 25.546366] k3s[841]: I0916 20:18:36.364526 841 repairip.go:210] Starting ipallocator-repair-controller machine # [ 25.547615] k3s[841]: I0916 20:18:36.364548 841 shared_informer.go:349] "Waiting for caches to sync" controller="ipallocator-repair-controller" machine # [ 25.603867] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Polling for API server readiness: GET /readyz failed: unknown" machine # [ 25.620457] k3s[841]: I0916 20:18:36.502340 841 shared_informer.go:377] "Caches are synced" machine # [ 25.622045] k3s[841]: I0916 20:18:36.503945 841 policy_source.go:248] refreshing policies machine # [ 25.665211] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Caches are synced" logger=k3s machine # [ 25.666698] k3s[841]: I0916 20:18:36.546881 841 apf_controller.go:382] Running API Priority and Fairness config worker machine # [ 25.672217] k3s[841]: I0916 20:18:36.546925 841 apf_controller.go:385] Running API Priority and Fairness periodic rebalancing process machine # [ 25.674031] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Caches are synced" logger=k3s machine # [ 25.675240] k3s[841]: I0916 20:18:36.548496 841 cache.go:39] Caches are synced for LocalAvailability controller machine # [ 25.680203] k3s[841]: time="2026-09-16T20:18:36Z" level=info msg="Caches are synced" logger=k3s machine # [ 25.681721] k3s[841]: I0916 20:18:36.550338 841 cache.go:39] Caches are synced for APIServiceRegistrationController controller machine # [ 25.683271] k3s[841]: I0916 20:18:36.551151 841 cache.go:39] Caches are synced for RemoteAvailability controller machine # [ 25.684901] k3s[841]: I0916 20:18:36.551211 841 handler_discovery.go:451] Starting ResourceDiscoveryManager machine # [ 25.686543] k3s[841]: I0916 20:18:36.560671 841 controller.go:667] quota admission added evaluator for: namespaces machine # [ 25.687935] k3s[841]: I0916 20:18:36.563443 841 shared_informer.go:356] "Caches are synced" controller="kubernetes-service-cidr-controller" machine # [ 25.692181] k3s[841]: I0916 20:18:36.563502 841 default_servicecidr_controller.go:169] Creating default ServiceCIDR with CIDRs: [10.43.0.0/16] machine # [ 25.694193] k3s[841]: I0916 20:18:36.565153 841 shared_informer.go:356] "Caches are synced" controller="ipallocator-repair-controller" machine # [ 25.695782] k3s[841]: I0916 20:18:36.565822 841 shared_informer.go:356] "Caches are synced" controller="crd-autoregister" machine # [ 25.699608] k3s[841]: I0916 20:18:36.565920 841 aggregator.go:187] initial CRD sync complete... machine # [ 25.700941] k3s[841]: I0916 20:18:36.566039 841 autoregister_controller.go:144] Starting autoregister controller machine # [ 25.702260] k3s[841]: I0916 20:18:36.566067 841 cache.go:32] Waiting for caches to sync for autoregister controller machine # [ 25.703613] k3s[841]: I0916 20:18:36.566079 841 cache.go:39] Caches are synced for autoregister controller machine # [ 25.709737] k3s[841]: I0916 20:18:36.591595 841 controller.go:667] quota admission added evaluator for: leases.coordination.k8s.io machine # [ 25.711428] k3s[841]: I0916 20:18:36.592072 841 cidrallocator.go:302] created ClusterIP allocator for Service CIDR 10.43.0.0/16 machine # [ 25.715197] k3s[841]: I0916 20:18:36.592277 841 default_servicecidr_controller.go:231] Setting default ServiceCIDR condition Ready to True machine # [ 25.718527] k3s[841]: I0916 20:18:36.600382 841 shared_informer.go:356] "Caches are synced" controller="node_authorizer" machine # [ 25.747352] k3s[841]: I0916 20:18:36.628758 841 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/16 machine # [ 25.771947] k3s[841]: E0916 20:18:36.653661 841 controller.go:95] Unable to perform initial Kubernetes service initialization: namespaces "default" not found machine # [ 26.480796] k3s[841]: I0916 20:18:37.362065 841 storage_scheduling.go:123] created PriorityClass system-node-critical with value 2000001000 machine # [ 26.489808] k3s[841]: I0916 20:18:37.371706 841 storage_scheduling.go:123] created PriorityClass system-cluster-critical with value 2000000000 machine # [ 26.491631] k3s[841]: I0916 20:18:37.372497 841 storage_scheduling.go:139] all system priority classes are created successfully or already exist. machine # [ 27.571529] k3s[841]: time="2026-09-16T20:18:38Z" 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/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/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" machine # [ 27.691222] k3s[841]: I0916 20:18:38.573047 841 controller.go:667] quota admission added evaluator for: roles.rbac.authorization.k8s.io machine # [ 27.728105] k3s[841]: I0916 20:18:38.607845 841 controller.go:667] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io machine # [ 27.793981] k3s[841]: I0916 20:18:38.675773 841 alloc.go:329] "allocated clusterIPs" service="default/kubernetes" clusterIPs={"IPv4":"10.43.0.1"} machine # [ 27.800850] k3s[841]: W0916 20:18:38.682536 841 lease.go:265] Resetting endpoints for master service "kubernetes" to [10.0.2.15] machine # [ 27.803463] k3s[841]: I0916 20:18:38.684842 841 controller.go:667] quota admission added evaluator for: endpoints machine # [ 27.808315] k3s[841]: I0916 20:18:38.688452 841 controller.go:667] quota admission added evaluator for: endpointslices.discovery.k8s.io machine # [ 28.723878] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported docker.io/rancher/klipper-helm:v0.13.3-build20260727" machine # [ 28.726662] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Tagged docker.io/rancher/klipper-helm@sha256:5425a2b4613d2458dbdff99218e8d487ebb59c20e7a941f061c0777070f0aac1" machine # [ 28.729660] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported docker.io/rancher/klipper-lb:v0.4.17" machine # [ 28.731559] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Tagged docker.io/rancher/klipper-lb@sha256:910944bb0bd94f060a82a56ca1ea1c577d3e49b3473a093a47a985f32e92d94a" machine # [ 28.734202] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported docker.io/rancher/local-path-provisioner:v0.0.37" machine # [ 28.735729] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Tagged docker.io/rancher/local-path-provisioner@sha256:e757967a5ec338f6a9b371c5a9688bedaa8c3578ea3dd4db329ea0084be0a86f" machine # [ 28.738491] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported docker.io/rancher/mirrored-coredns-coredns:1.14.6" machine # [ 28.740316] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Tagged docker.io/rancher/mirrored-coredns-coredns@sha256:900f9c109f7a33545d3c811516e8376df9019147b750f5ce3e254468769176ea" machine # [ 28.742915] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported docker.io/rancher/mirrored-library-busybox:1.37.0" machine # [ 28.744938] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Tagged docker.io/rancher/mirrored-library-busybox@sha256:101b4afd76732482eff9b95cae5f94bcf295e521fbec4e01b69c5421f3f3f3e5" machine # [ 28.747327] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported docker.io/rancher/mirrored-library-traefik:3.7.8" machine # [ 28.748773] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Tagged docker.io/rancher/mirrored-library-traefik@sha256:4299bbed850421258fc5448c2e0e6ad350981d4d335a68de11b92448aedbefe5" machine # [ 28.750780] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported docker.io/rancher/mirrored-metrics-server:v0.9.0" machine # [ 28.752406] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Tagged docker.io/rancher/mirrored-metrics-server@sha256:d9862115e7c7881280d3d75ca26bda8ffc0fc213315979575bf23ce9826205c0" machine # [ 28.754975] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported docker.io/rancher/mirrored-pause:3.10.2" machine # [ 28.756282] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Tagged docker.io/rancher/mirrored-pause@sha256:f548e0e8e3dc1896ca956272154dde3314e8cc4fde0a57577ee9fa1c63f5baf4" machine # [ 28.939381] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Imported 8 images from /var/lib/rancher/k3s/agent/images/k3s-airgap-images-arm64.tar.zst in 4.268465s" machine # [ 28.941655] k3s[841]: time="2026-09-16T20:18:39Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/niks3-server.tar" machine # [ 29.188333] k3s[841]: time="2026-09-16T20:18:40Z" 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::9a9d:43f9:43e1:fefd --node-labels= --read-only-port=0" machine # [ 29.432298] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Imported docker.io/library/niks3-server:1.4.0-aarch64-linux" machine # [ 29.434829] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Tagged docker.io/library/niks3-server@sha256:8d889bcf6b96bd34dbe8e6d9e61e5b45c2f94730c9f92fd982b26007e97b877b" machine # [ 29.460903] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Imported 1 images from /var/lib/rancher/k3s/agent/images/niks3-server.tar in 519.24846ms" machine # [ 29.577708] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Waiting for untainted node" machine # [ 29.584390] k3s[841]: 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. machine # [ 29.600157] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Creating k3s-supervisor event broadcaster" machine # [ 29.606612] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Kube API server is now running" machine # [ 29.609546] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="k3s is up and running" machine # [ 29.615091] systemd[1]: Started k3s service. machine # [ 29.616709] systemd[1]: Reached target Multi-User System. machine # [ 29.618220] systemd[1]: Startup finished in 698ms (kernel) + 4.048s (initrd) + 24.852s (userspace) = 29.599s. machine # [ 29.625038] k3s[841]: time="2026-09-16T20:18:40Z" 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=Normal machine # [ 29.656966] k3s[841]: I0916 20:18:40.538762 841 server.go:521] "Kubelet version" kubeletVersion="v1.35.8+k3s1" machine # [ 29.661356] k3s[841]: I0916 20:18:40.538813 841 server.go:523] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 29.666523] k3s[841]: I0916 20:18:40.541202 841 watchdog_linux.go:95] "Systemd watchdog is not enabled" machine # [ 29.668945] k3s[841]: I0916 20:18:40.541243 841 watchdog_linux.go:138] "Systemd watchdog is not enabled or the interval is invalid, so health checking will not be started." machine # [ 29.673796] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Creating embedded CRD addons.k3s.cattle.io" machine # [ 29.675562] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Creating embedded CRD etcdsnapshotfiles.k3s.cattle.io" machine # [ 29.680226] k3s[841]: I0916 20:18:40.562133 841 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt" machine # [ 29.690321] k3s[841]: I0916 20:18:40.572209 841 controllermanager.go:189] "Starting" version="v1.35.8+k3s1" machine # [ 29.696157] k3s[841]: I0916 20:18:40.574057 841 controllermanager.go:191] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 29.701688] k3s[841]: I0916 20:18:40.583575 841 secure_serving.go:211] Serving securely on 127.0.0.1:10257 machine # [ 29.703158] k3s[841]: I0916 20:18:40.584482 841 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController machine # [ 29.704844] k3s[841]: I0916 20:18:40.584512 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.706138] k3s[841]: I0916 20:18:40.584551 841 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" machine # [ 29.710830] k3s[841]: I0916 20:18:40.584675 841 tlsconfig.go:243] "Starting DynamicServingCertificateController" machine # [ 29.713135] k3s[841]: I0916 20:18:40.584743 841 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 29.715229] k3s[841]: I0916 20:18:40.584762 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.718608] k3s[841]: I0916 20:18:40.584779 841 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 29.724185] k3s[841]: I0916 20:18:40.584796 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.726325] k3s[841]: I0916 20:18:40.593419 841 server.go:1414] "Using cgroup driver setting received from the CRI runtime" cgroupDriver="systemd" machine # [ 29.729893] k3s[841]: I0916 20:18:40.599662 841 server.go:771] "--cgroups-per-qos enabled, but --cgroup-root was not specified. Defaulting to /" machine # [ 29.732436] k3s[841]: I0916 20:18:40.599747 841 server.go:832] "NoSwap is set due to memorySwapBehavior not specified" memorySwapBehavior="" FailSwapOn=false machine # [ 29.735043] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Creating embedded CRD helmcharts.helm.cattle.io" machine # [ 29.737100] k3s[841]: I0916 20:18:40.600374 841 container_manager_linux.go:272] "Container manager verified user specified cgroup-root exists" cgroupRoot=[] machine # [ 29.739787] k3s[841]: I0916 20:18:40.600415 841 container_manager_linux.go:277] "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,"PodPidsLimit":-1,"EnforceCPULimits":true,"CPUCFSQuotaPeriod":100000000,"TopologyManagerPolicy":"none","TopologyManagerPolicyOptions":null,"CgroupVersion":2} machine # [ 29.758149] k3s[841]: I0916 20:18:40.604397 841 topology_manager.go:143] "Creating topology manager with none policy" machine # [ 29.759814] k3s[841]: I0916 20:18:40.604440 841 container_manager_linux.go:308] "Creating device plugin manager" machine # [ 29.762627] k3s[841]: I0916 20:18:40.604622 841 container_manager_linux.go:317] "Creating Dynamic Resource Allocation (DRA) manager" machine # [ 29.764519] k3s[841]: I0916 20:18:40.614703 841 state_mem.go:41] "Initialized" logger="CPUManager state memory" machine # [ 29.766021] k3s[841]: I0916 20:18:40.614977 841 kubelet.go:482] "Attempting to sync node with API server" machine # [ 29.767425] k3s[841]: I0916 20:18:40.615356 841 kubelet.go:383] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests" machine # [ 29.769259] k3s[841]: I0916 20:18:40.615553 841 kubelet.go:394] "Adding apiserver pod source" machine # [ 29.770459] k3s[841]: I0916 20:18:40.615788 841 apiserver.go:42] "Waiting for node sync before watching apiserver pods" machine # [ 29.771949] k3s[841]: I0916 20:18:40.620564 841 kuberuntime_manager.go:304] "Container runtime initialized" containerRuntime="containerd" version="2.2.7-k3s1" apiVersion="v1" machine # [ 29.774155] k3s[841]: I0916 20:18:40.632759 841 kubelet.go:945] "Not starting ClusterTrustBundle informer because we are in static kubelet mode or the ClusterTrustBundleProjection featuregate is disabled" machine # [ 29.776553] k3s[841]: I0916 20:18:40.632798 841 kubelet.go:972] "Not starting PodCertificateRequest manager because we are in static kubelet mode or the PodCertificateProjection feature gate is disabled" machine # [ 29.778934] k3s[841]: W0916 20:18:40.632875 841 probe.go:272] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating. machine # [ 29.781124] k3s[841]: I0916 20:18:40.640442 841 controller.go:667] quota admission added evaluator for: serviceaccounts machine # [ 29.782714] k3s[841]: I0916 20:18:40.645097 841 server.go:1252] "Started kubelet" machine # [ 29.783780] k3s[841]: I0916 20:18:40.651942 841 fs_resource_analyzer.go:69] "Starting FS ResourceAnalyzer" machine # [ 29.785186] k3s[841]: I0916 20:18:40.652749 841 server.go:182] "Starting to listen" address="0.0.0.0" port=10250 machine # [ 29.786498] k3s[841]: I0916 20:18:40.653561 841 server.go:317] "Adding debug handlers to kubelet server" machine # [ 29.787743] k3s[841]: I0916 20:18:40.657115 841 ratelimit.go:56] "Setting rate limiting for endpoint" service="podresources" qps=100 burstTokens=10 machine # [ 29.789624] k3s[841]: I0916 20:18:40.657221 841 server_v1.go:49] "podresources" method="list" useActivePods=true machine # [ 29.791276] k3s[841]: I0916 20:18:40.657401 841 server.go:254] "Starting to serve the podresources API" endpoint="unix:/var/lib/kubelet/pod-resources/kubelet.sock" machine # [ 29.793238] k3s[841]: I0916 20:18:40.657699 841 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" machine # [ 29.795746] k3s[841]: I0916 20:18:40.659197 841 volume_manager.go:311] "Starting Kubelet Volume Manager" machine # [ 29.797073] k3s[841]: E0916 20:18:40.659622 841 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found" machine # [ 29.798795] k3s[841]: I0916 20:18:40.660060 841 desired_state_of_world_populator.go:146] "Desired state populator starts to run" machine # [ 29.800383] k3s[841]: I0916 20:18:40.660134 841 reconciler.go:29] "Reconciler: start to sync state" machine # [ 29.801752] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Creating embedded CRD helmchartconfigs.helm.cattle.io" machine # [ 29.808916] k3s[841]: I0916 20:18:40.690725 841 factory.go:223] Registration of the systemd container factory successfully machine # [ 29.811282] k3s[841]: I0916 20:18:40.692532 841 factory.go:221] 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 directory machine # [ 29.814191] k3s[841]: I0916 20:18:40.693814 841 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager machine # [ 29.819678] k3s[841]: I0916 20:18:40.701587 841 factory.go:223] Registration of the containerd container factory successfully machine # [ 29.825242] k3s[841]: E0916 20:18:40.702641 841 kubelet.go:1661] "Image garbage collection failed once. Stats initialization may not have completed yet" err="invalid capacity 0 on image filesystem" machine # [ 29.851343] k3s[841]: I0916 20:18:40.733261 841 cpu_manager.go:225] "Starting" policy="none" machine # [ 29.852800] k3s[841]: I0916 20:18:40.734697 841 cpu_manager.go:226] "Reconciling" reconcilePeriod="10s" machine # [ 29.854504] k3s[841]: I0916 20:18:40.736063 841 state_mem.go:41] "Initialized" logger="CPUManager state checkpoint.CPUManager state memory" machine # [ 29.857886] k3s[841]: I0916 20:18:40.739808 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.859385] k3s[841]: time="2026-09-16T20:18:40Z" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available" machine # [ 29.861713] k3s[841]: E0916 20:18:40.742230 841 nodelease.go:50] "Failed to get node when trying to set owner ref to the node lease" err="nodes \"machine\" not found" node="machine" machine # [ 29.863862] k3s[841]: I0916 20:18:40.744010 841 policy_none.go:50] "Start" machine # [ 29.866634] k3s[841]: I0916 20:18:40.744045 841 memory_manager.go:187] "Starting memorymanager" policy="None" machine # [ 29.872173] k3s[841]: I0916 20:18:40.744070 841 state_mem.go:36] "Initializing new in-memory state store" logger="Memory Manager state checkpoint" machine # [ 29.873923] k3s[841]: I0916 20:18:40.752369 841 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager machine # [ 29.875314] k3s[841]: I0916 20:18:40.752663 841 policy_none.go:44] "Start" machine # [ 29.876300] k3s[841]: I0916 20:18:40.754458 841 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv6" machine # [ 29.883878] k3s[841]: E0916 20:18:40.765668 841 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found" machine # [ 29.902678] k3s[841]: I0916 20:18:40.784596 841 shared_informer.go:377] "Caches are synced" machine # [ 29.907571] systemd[1]: Created slice libcontainer container kubepods.slice. machine # [ 29.909583] k3s[841]: I0916 20:18:40.784917 841 shared_informer.go:377] "Caches are synced" machine # [ 29.911419] k3s[841]: I0916 20:18:40.788710 841 shared_informer.go:377] "Caches are synced" machine # [ 29.953845] k3s[841]: I0916 20:18:40.835331 841 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv4" machine # [ 29.955302] k3s[841]: I0916 20:18:40.835400 841 status_manager.go:249] "Starting to sync pod status with apiserver" machine # [ 29.957016] k3s[841]: I0916 20:18:40.835425 841 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager machine # [ 29.958334] k3s[841]: I0916 20:18:40.835458 841 kubelet.go:2506] "Starting kubelet main sync loop" machine # [ 29.959435] k3s[841]: E0916 20:18:40.835588 841 kubelet.go:2530] "Skipping pod synchronization" err="[container runtime status check may not have completed yet, PLEG is not healthy: pleg has yet to be successful]" machine # [ 29.970687] k3s[841]: I0916 20:18:40.852554 841 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager machine # [ 29.976556] systemd[1]: Created slice libcontainer container kubepods-burstable.slice. machine: (finished: waiting for unit k3s.service, in 31.11 seconds) machine # [ 29.984169] k3s[841]: E0916 20:18:40.865959 841 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found" machine: waiting for unit rustfs-setup.service machine # [ 29.987286] systemd[1]: Created slice libcontainer container kubepods-besteffort.slice. machine # [ 30.006719] k3s[841]: E0916 20:18:40.887900 841 manager.go:525] "Failed to read data from checkpoint" err="checkpoint is not found" checkpoint="kubelet_internal_checkpoint" machine # [ 30.009251] k3s[841]: I0916 20:18:40.890927 841 eviction_manager.go:194] "Eviction manager: starting control loop" machine # [ 30.010713] k3s[841]: I0916 20:18:40.890968 841 container_log_manager.go:146] "Initializing container log rotate workers" workers=1 monitorPeriod="10s" machine # [ 30.018938] k3s[841]: I0916 20:18:40.891836 841 plugin_manager.go:121] "Starting Kubelet Plugin Manager" machine # [ 30.021835] k3s[841]: E0916 20:18:40.896223 841 eviction_manager.go:272] "eviction manager: failed to check if we have separate container filesystem. Ignoring." err="no imagefs label for configured runtime" machine # [ 30.024210] k3s[841]: E0916 20:18:40.896389 841 eviction_manager.go:297] "Eviction manager: failed to get summary stats" err="failed to get node info: node \"machine\" not found" machine: (finished: waiting for unit rustfs-setup.service, in 0.05 seconds) machine: waiting for unit postgresql.service machine: (finished: waiting for unit postgresql.service, in 0.04 seconds) subtest: chart deploys and becomes ready ??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/yyamlhbvx0lp00fbf9sswdcq9ckfh7qj-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39 machine: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s ??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/yyamlhbvx0lp00fbf9sswdcq9ckfh7qj-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39 machine # [ 30.115761] k3s[841]: I0916 20:18:40.997602 841 kubelet_node_status.go:74] "Attempting to register node" node="machine" machine # [ 30.129171] k3s[841]: I0916 20:18:41.010371 841 range_allocator.go:113] "No Secondary Service CIDR provided. Skipping filtering out secondary service addresses" logger="node-ipam-controller" machine # [ 30.132446] k3s[841]: I0916 20:18:41.010447 841 controllermanager.go:627] "Warning: controller is disabled" controller="selinux-warning-controller" machine # [ 30.136838] k3s[841]: I0916 20:18:41.010783 841 kubelet_node_status.go:77] "Successfully registered node" node="machine" machine # [ 30.151770] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Annotations and labels have been set successfully on node: machine" machine # [ 30.160259] k3s[841]: I0916 20:18:41.042106 841 shared_informer.go:377] "Caches are synced" machine # [ 30.163473] k3s[841]: I0916 20:18:41.042172 841 server.go:218] "Successfully retrieved NodeIPs" NodeIPs=["10.0.2.15","fec0::9a9d:43f9:43e1:fefd"] machine # [ 30.166785] k3s[841]: E0916 20:18:41.042227 841 server.go:255] "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`" machine # [ 30.180891] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Starting flannel with backend vxlan" machine # [ 30.235164] k3s[841]: I0916 20:18:41.116964 841 controllermanager.go:627] "Warning: controller is disabled" controller="service-lb-controller" machine # [ 30.240680] k3s[841]: I0916 20:18:41.122567 841 server.go:264] "kube-proxy running in dual-stack mode" primary ipFamily="IPv4" machine # [ 30.242318] k3s[841]: I0916 20:18:41.124250 841 server_linux.go:136] "Using iptables Proxier" machine # [ 30.270831] k3s[841]: I0916 20:18:41.152689 841 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="podcertificaterequest-cleaner-controller" requiredFeatureGates=["PodCertificateRequest"] machine # [ 30.275728] k3s[841]: I0916 20:18:41.155680 841 controllermanager.go:579] "Warning: skipping controller" controller="podcertificaterequest-cleaner-controller" machine # [ 30.287289] k3s[841]: I0916 20:18:41.169176 841 kubelet_node_status.go:427] "Fast updating node status as it just became ready" machine # [ 30.305832] k3s[841]: I0916 20:18:41.186789 841 proxier.go:242] "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" machine # [ 30.311960] k3s[841]: I0916 20:18:41.186850 841 controllermanager.go:627] "Warning: controller is disabled" controller="node-route-controller" machine # [ 30.314279] k3s[841]: I0916 20:18:41.186876 841 controllermanager.go:627] "Warning: controller is disabled" controller="cloud-node-lifecycle-controller" machine # [ 30.317241] k3s[841]: I0916 20:18:41.199131 841 server.go:529] "Version info" version="v1.35.8+k3s1" machine # [ 30.318676] k3s[841]: I0916 20:18:41.199188 841 server.go:531] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 30.331163] k3s[841]: I0916 20:18:41.213005 841 config.go:200] "Starting service config controller" machine # [ 30.332542] k3s[841]: I0916 20:18:41.213036 841 shared_informer.go:349] "Waiting for caches to sync" controller="service config" machine # [ 30.334020] k3s[841]: I0916 20:18:41.213055 841 config.go:106] "Starting endpoint slice config controller" machine # [ 30.335275] k3s[841]: I0916 20:18:41.213063 841 shared_informer.go:349] "Waiting for caches to sync" controller="endpoint slice config" machine # [ 30.337310] k3s[841]: I0916 20:18:41.213078 841 config.go:403] "Starting serviceCIDR config controller" machine # [ 30.338765] k3s[841]: I0916 20:18:41.213088 841 shared_informer.go:349] "Waiting for caches to sync" controller="serviceCIDR config" machine # [ 30.341789] k3s[841]: I0916 20:18:41.213716 841 config.go:309] "Starting node config controller" machine # [ 30.342961] k3s[841]: I0916 20:18:41.213729 841 shared_informer.go:349] "Waiting for caches to sync" controller="node config" machine # [ 30.344666] k3s[841]: I0916 20:18:41.213738 841 shared_informer.go:356] "Caches are synced" controller="node config" machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 30.458173] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available" machine # [ 30.462447] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Waiting for CRD helmchartconfigs.helm.cattle.io to become available" machine # [ 30.466066] k3s[841]: I0916 20:18:41.340932 841 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller" requiredFeatureGates=["ClusterTrustBundle"] machine # [ 30.471805] k3s[841]: I0916 20:18:41.342632 841 controllermanager.go:579] "Warning: skipping controller" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller" machine # [ 30.475994] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Done waiting for CRD helmchartconfigs.helm.cattle.io to become available" machine # [ 30.478861] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-40.1.4+up40.1.0.tgz" machine # [ 30.482066] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-40.1.4+up40.1.0.tgz" machine # [ 30.485225] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml" machine # [ 30.487586] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml" machine # [ 30.490043] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml" machine # [ 30.492482] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml" machine # [ 30.494775] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/runtimes.yaml" machine # [ 30.497062] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml" machine # [ 30.531628] k3s[841]: I0916 20:18:41.413416 841 shared_informer.go:356] "Caches are synced" controller="serviceCIDR config" machine # [ 30.534561] k3s[841]: I0916 20:18:41.413469 841 shared_informer.go:356] "Caches are synced" controller="service config" machine # [ 30.536798] k3s[841]: I0916 20:18:41.413495 841 shared_informer.go:356] "Caches are synced" controller="endpoint slice config" machine # [ 30.609008] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Starting dynamiclistener CN filter node controller with SANs: [127.0.0.1 ::1 localhost machine 10.0.2.15 fec0::9a9d:43f9:43e1:fefd 10.43.0.1 kubernetes kubernetes.default kubernetes.default.svc kubernetes.default.svc.cluster.local]" machine # [ 30.614165] k3s[841]: time="2026-09-16T20:18:41Z" level=info msg="Tunnel server egress proxy mode: agent" machine # [ 30.736366] k3s[841]: I0916 20:18:41.617556 841 apiserver.go:52] "Watching apiserver" machine # [ 30.904721] k3s[841]: I0916 20:18:41.786588 841 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="device-taint-eviction-controller" requiredFeatureGates=["DynamicResourceAllocation","DRADeviceTaints"] machine # [ 30.907437] k3s[841]: I0916 20:18:41.786639 841 controllermanager.go:579] "Warning: skipping controller" controller="device-taint-eviction-controller" machine # [ 30.978453] k3s[841]: I0916 20:18:41.860333 841 desired_state_of_world_populator.go:154] "Finished populating initial desired state of world" machine # [ 31.106204] k3s[841]: I0916 20:18:41.987997 841 controllermanager.go:579] "Warning: skipping controller" controller="storage-version-migrator-controller" machine # [ 31.315078] k3s[841]: time="2026-09-16T20:18:42Z" 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__9a9d_43f9_43e1_fefd-72ee68:fec0::9a9d:43f9:43e1:fefd 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=E55BEF79FB284E110024603AC7D1958AC8FD8344]" machine # [ 31.342783] k3s[841]: time="2026-09-16T20:18:42Z" level=info msg="Active TLS secret kube-system/k3s-serving (ver=256) (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__9a9d_43f9_43e1_fefd-72ee68:fec0::9a9d:43f9:43e1:fefd 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=E55BEF79FB284E110024603AC7D1958AC8FD8344]" machine # [ 31.425675] k3s[841]: I0916 20:18:42.306898 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="horizontalpodautoscalers.autoscaling" machine # [ 31.431704] k3s[841]: I0916 20:18:42.307025 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpoints" machine # [ 31.436788] k3s[841]: I0916 20:18:42.307060 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="controllerrevisions.apps" machine # [ 31.441737] k3s[841]: I0916 20:18:42.307115 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="networkpolicies.networking.k8s.io" machine # [ 31.446500] k3s[841]: I0916 20:18:42.307218 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmcharts.helm.cattle.io" machine # [ 31.452882] k3s[841]: I0916 20:18:42.307298 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="deployments.apps" machine # [ 31.456722] k3s[841]: I0916 20:18:42.307348 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="poddisruptionbudgets.policy" machine # [ 31.461766] k3s[841]: I0916 20:18:42.307385 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="addons.k3s.cattle.io" machine # [ 31.466821] k3s[841]: I0916 20:18:42.307425 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="cronjobs.batch" machine # [ 31.470145] k3s[841]: I0916 20:18:42.307457 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="replicasets.apps" machine # [ 31.473405] k3s[841]: I0916 20:18:42.307492 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="ingresses.networking.k8s.io" machine # [ 31.476776] k3s[841]: I0916 20:18:42.307535 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="rolebindings.rbac.authorization.k8s.io" machine # [ 31.480306] k3s[841]: I0916 20:18:42.307571 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpointslices.discovery.k8s.io" machine # [ 31.483728] k3s[841]: I0916 20:18:42.307608 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="resourceclaimtemplates.resource.k8s.io" machine # [ 31.487443] k3s[841]: I0916 20:18:42.307651 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmchartconfigs.helm.cattle.io" machine # [ 31.490880] k3s[841]: I0916 20:18:42.307722 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="jobs.batch" machine # [ 31.493840] k3s[841]: I0916 20:18:42.307758 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="roles.rbac.authorization.k8s.io" machine # [ 31.496937] k3s[841]: I0916 20:18:42.307798 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="csistoragecapacities.storage.k8s.io" machine # [ 31.499934] k3s[841]: I0916 20:18:42.307880 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="leases.coordination.k8s.io" machine # [ 31.502903] k3s[841]: I0916 20:18:42.307938 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="statefulsets.apps" machine # [ 31.505627] k3s[841]: I0916 20:18:42.307992 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="podtemplates" machine # [ 31.508103] k3s[841]: I0916 20:18:42.308025 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="serviceaccounts" machine # [ 31.510483] k3s[841]: I0916 20:18:42.308102 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="limitranges" machine # [ 31.512876] k3s[841]: I0916 20:18:42.308145 841 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="daemonsets.apps" machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 31.833186] k3s[841]: time="2026-09-16T20:18:42Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller" machine # [ 31.844593] k3s[841]: time="2026-09-16T20:18:42Z" level=info msg="Creating deploy event broadcaster" machine # [ 31.848545] k3s[841]: I0916 20:18:42.718665 841 controller.go:667] quota admission added evaluator for: addons.k3s.cattle.io machine # [ 31.860239] k3s[841]: time="2026-09-16T20:18:42Z" 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=Normal machine # [ 31.872409] k3s[841]: time="2026-09-16T20:18:42Z" level=info msg="Starting /v1, Kind=Node controller" machine # [ 31.875213] k3s[841]: time="2026-09-16T20:18:42Z" level=info msg="Creating helm-controller event broadcaster" machine # [ 31.884278] k3s[841]: time="2026-09-16T20:18:42Z" level=info msg="Labels and annotations have been set successfully on node: machine" machine # [ 31.891833] k3s[841]: time="2026-09-16T20:18:42Z" level=info msg="Cluster dns configmap has been set successfully" machine # [ 32.192331] k3s[841]: time="2026-09-16T20:18:43Z" 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=Normal machine # [ 32.224865] k3s[841]: time="2026-09-16T20:18:43Z" 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=Normal machine # [ 32.692117] k3s[841]: I0916 20:18:43.570822 841 node_lifecycle_controller.go:419] "Controller will reconcile labels" logger="node-lifecycle-controller" machine # [ 32.694000] k3s[841]: time="2026-09-16T20:18:43Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Deferred node password secret validation complete" object=machine reason=NodePasswordValidationComplete type=Normal machine # [ 32.704051] k3s[841]: time="2026-09-16T20:18:43Z" 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=Normal machine # [ 32.740154] k3s[841]: time="2026-09-16T20:18:43Z" 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=Normal machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 32.955030] k3s[841]: I0916 20:18:43.836397 841 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="storageversion-garbage-collector-controller" requiredFeatureGates=["APIServerIdentity","StorageVersionAPI"] machine # [ 32.960214] k3s[841]: I0916 20:18:43.839844 841 controllermanager.go:579] "Warning: skipping controller" controller="storageversion-garbage-collector-controller" machine # [ 32.974634] k3s[841]: I0916 20:18:43.856493 841 serving.go:392] Generated self-signed cert in-memory machine # [ 33.212265] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding controller" machine # [ 33.228276] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting batch/v1, Kind=Job controller" machine # [ 33.236310] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting /v1, Kind=ConfigMap controller" machine # [ 33.238631] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting /v1, Kind=ServiceAccount controller" machine # [ 33.241018] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting /v1, Kind=Secret controller" machine # [ 33.245264] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller" machine # [ 33.248387] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller" machine # [ 33.252180] k3s[841]: I0916 20:18:44.132161 841 serving.go:392] Generated self-signed cert in-memory machine # [ 33.362799] k3s[841]: I0916 20:18:44.244599 841 controllermanager.go:160] Version: v1.35.8+k3s1 machine # [ 33.369309] k3s[841]: I0916 20:18:44.251065 841 secure_serving.go:211] Serving securely on 127.0.0.1:10258 machine # [ 33.373569] k3s[841]: I0916 20:18:44.251836 841 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController machine # [ 33.378118] k3s[841]: I0916 20:18:44.251865 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 33.382128] k3s[841]: I0916 20:18:44.251900 841 tlsconfig.go:243] "Starting DynamicServingCertificateController" machine # [ 33.386341] k3s[841]: I0916 20:18:44.252005 841 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 33.392506] k3s[841]: I0916 20:18:44.252023 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 33.395591] k3s[841]: I0916 20:18:44.252037 841 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 33.401080] k3s[841]: I0916 20:18:44.252050 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 33.403917] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Creating service-lb-controller event broadcaster" machine # [ 33.406793] k3s[841]: I0916 20:18:44.277871 841 controller.go:667] quota admission added evaluator for: deployments.apps machine # [ 33.472284] k3s[841]: I0916 20:18:44.352567 841 shared_informer.go:377] "Caches are synced" machine # [ 33.475934] k3s[841]: I0916 20:18:44.352664 841 shared_informer.go:377] "Caches are synced" machine # [ 33.480395] k3s[841]: I0916 20:18:44.352628 841 shared_informer.go:377] "Caches are synced" machine # [ 33.526637] k3s[841]: I0916 20:18:44.408231 841 alloc.go:329] "allocated clusterIPs" service="kube-system/kube-dns" clusterIPs={"IPv4":"10.43.0.10"} machine # [ 33.533784] k3s[841]: time="2026-09-16T20:18:44Z" 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=Normal machine # [ 33.730202] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting /v1, Kind=Node controller" machine # [ 33.742334] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting /v1, Kind=Pod controller" machine # [ 33.754512] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting apps/v1, Kind=DaemonSet controller" machine # [ 33.768188] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Starting discovery.k8s.io/v1, Kind=EndpointSlice controller" machine # [ 33.773043] k3s[841]: I0916 20:18:44.647475 841 controllermanager.go:329] Started "cloud-node-controller" machine # [ 33.779455] k3s[841]: I0916 20:18:44.648030 841 controllermanager.go:329] Started "cloud-node-lifecycle-controller" machine # [ 33.784064] k3s[841]: I0916 20:18:44.648678 841 node_controller.go:176] Sending events to api server. machine # [ 33.787412] k3s[841]: I0916 20:18:44.648790 841 node_lifecycle_controller.go:112] Sending events to api server machine # [ 33.791115] k3s[841]: I0916 20:18:44.649122 841 controllermanager.go:329] Started "service-lb-controller" machine # [ 33.794479] k3s[841]: W0916 20:18:44.649150 841 controllermanager.go:306] "node-route-controller" is disabled machine # [ 33.797799] k3s[841]: I0916 20:18:44.650741 841 node_controller.go:185] Waiting for informer caches to sync machine # [ 33.800834] k3s[841]: I0916 20:18:44.651069 841 controller.go:235] Starting service controller machine # [ 33.803533] k3s[841]: I0916 20:18:44.651124 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 33.856206] k3s[841]: I0916 20:18:44.737929 841 controllermanager.go:627] "Warning: controller is disabled" controller="bootstrap-signer-controller" machine # [ 33.870899] k3s[841]: I0916 20:18:44.751572 841 shared_informer.go:377] "Caches are synced" machine # [ 33.874631] k3s[841]: I0916 20:18:44.751729 841 node_controller.go:429] Initializing node machine with cloud provider machine # [ 33.890530] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Adding node OwnerReference to node-password secret machine.node-password.k3s" machine # [ 33.914566] k3s[841]: I0916 20:18:44.795981 841 node_controller.go:474] Successfully initialized node machine with cloud provider machine # [ 33.920231] k3s[841]: I0916 20:18:44.797255 841 event.go:389] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="v1" type="Normal" reason="Synced" message="Node synced successfully" machine # [ 33.924941] k3s[841]: time="2026-09-16T20:18:44Z" level=info msg="Synced coredns NodeHosts entries for machine" machine # [ 33.931649] k3s[841]: I0916 20:18:44.813483 841 server.go:173] "Starting Kubernetes Scheduler" version="v1.35.8+k3s1" machine # [ 33.934772] k3s[841]: I0916 20:18:44.813543 841 server.go:175] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 33.942276] k3s[841]: I0916 20:18:44.822875 841 secure_serving.go:211] Serving securely on 127.0.0.1:10259 machine # [ 33.945995] k3s[841]: I0916 20:18:44.823041 841 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController machine # [ 33.952488] k3s[841]: I0916 20:18:44.823069 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 33.955747] k3s[841]: I0916 20:18:44.823123 841 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" machine # [ 33.967559] k3s[841]: I0916 20:18:44.823326 841 tlsconfig.go:243] "Starting DynamicServingCertificateController" machine # [ 33.970695] k3s[841]: I0916 20:18:44.832189 841 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 33.979070] k3s[841]: I0916 20:18:44.832258 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 33.982995] k3s[841]: I0916 20:18:44.832289 841 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 33.990067] k3s[841]: I0916 20:18:44.832311 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.168412] k3s[841]: time="2026-09-16T20:18:45Z" 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=Normal machine # [ 34.185010] k3s[841]: time="2026-09-16T20:18:45Z" 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=Normal machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 34.241834] k3s[841]: I0916 20:18:45.123706 841 shared_informer.go:377] "Caches are synced" machine # [ 34.252104] k3s[841]: I0916 20:18:45.133033 841 shared_informer.go:377] "Caches are synced" machine # [ 34.253848] k3s[841]: I0916 20:18:45.133123 841 shared_informer.go:377] "Caches are synced" machine # [ 34.316124] k3s[841]: I0916 20:18:45.195473 841 controller.go:667] quota admission added evaluator for: helmcharts.helm.cattle.io machine # [ 34.324321] k3s[841]: time="2026-09-16T20:18:45Z" 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=Normal machine # [ 34.339986] k3s[841]: I0916 20:18:45.221820 841 endpointslice_controller.go:283] "Starting endpoint slice controller" machine # [ 34.348264] k3s[841]: I0916 20:18:45.224771 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.350370] k3s[841]: I0916 20:18:45.226010 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.352492] k3s[841]: I0916 20:18:45.226177 841 replica_set.go:241] "Starting controller" name="replicationcontroller" machine # [ 34.354648] k3s[841]: I0916 20:18:45.226203 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.356543] k3s[841]: I0916 20:18:45.226246 841 gc_controller.go:98] "Starting GC controller" machine # [ 34.358228] k3s[841]: I0916 20:18:45.226262 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.360000] k3s[841]: I0916 20:18:45.226343 841 daemon_controller.go:309] "Starting daemon sets controller" machine # [ 34.365879] k3s[841]: I0916 20:18:45.226359 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.367540] k3s[841]: I0916 20:18:45.226478 841 node_ipam_controller.go:142] "Starting ipam controller" machine # [ 34.372115] k3s[841]: I0916 20:18:45.226502 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.373657] k3s[841]: I0916 20:18:45.226819 841 deployment_controller.go:172] "Starting controller" controller="deployment" machine # [ 34.375484] k3s[841]: I0916 20:18:45.226840 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.380114] k3s[841]: I0916 20:18:45.226901 841 replica_set.go:241] "Starting controller" name="replicaset" machine # [ 34.381643] k3s[841]: I0916 20:18:45.226917 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.383047] k3s[841]: I0916 20:18:45.227031 841 cronjob_controllerv2.go:143] "Starting cronjob controller v2" machine # [ 34.388137] k3s[841]: I0916 20:18:45.227049 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.389506] k3s[841]: I0916 20:18:45.227155 841 attach_detach_controller.go:335] "Starting attach detach controller" machine # [ 34.391007] k3s[841]: I0916 20:18:45.227173 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.392373] k3s[841]: I0916 20:18:45.227226 841 taint_eviction.go:283] "Starting" controller="taint-eviction-controller" machine # [ 34.393847] k3s[841]: I0916 20:18:45.227271 841 taint_eviction.go:288] "Sending events to API server" machine # [ 34.395134] k3s[841]: I0916 20:18:45.227281 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.400117] k3s[841]: I0916 20:18:45.227368 841 endpointslicemirroring_controller.go:226] "Starting EndpointSliceMirroring controller" machine # [ 34.401778] k3s[841]: I0916 20:18:45.227385 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.403008] k3s[841]: I0916 20:18:45.227438 841 serviceaccounts_controller.go:117] "Starting service account controller" machine # [ 34.408105] k3s[841]: I0916 20:18:45.227461 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.409346] k3s[841]: I0916 20:18:45.227506 841 ttl_controller.go:127] "Starting TTL controller" machine # [ 34.410521] k3s[841]: I0916 20:18:45.227524 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.411722] k3s[841]: I0916 20:18:45.227565 841 pvc_protection_controller.go:166] "Starting PVC protection controller" machine # [ 34.413211] k3s[841]: I0916 20:18:45.227582 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.414404] k3s[841]: I0916 20:18:45.227613 841 tokencleaner.go:117] "Starting token cleaner controller" machine # [ 34.415655] k3s[841]: I0916 20:18:45.227628 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.416937] k3s[841]: I0916 20:18:45.227656 841 clusterroleaggregation_controller.go:194] "Starting ClusterRoleAggregator controller" machine # [ 34.418451] k3s[841]: I0916 20:18:45.227671 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.419664] k3s[841]: I0916 20:18:45.227711 841 controller.go:174] "Starting ephemeral volume controller" machine # [ 34.421004] k3s[841]: I0916 20:18:45.227727 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.422205] k3s[841]: I0916 20:18:45.227752 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.423372] k3s[841]: I0916 20:18:45.228030 841 namespace_controller.go:202] "Starting namespace controller" machine # [ 34.424695] k3s[841]: I0916 20:18:45.228057 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.425857] k3s[841]: I0916 20:18:45.228093 841 publisher.go:107] "Starting root CA cert publisher controller" machine # [ 34.427118] k3s[841]: I0916 20:18:45.228108 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.428306] k3s[841]: I0916 20:18:45.228195 841 controller.go:423] "Starting resource claim controller" machine # [ 34.429491] k3s[841]: I0916 20:18:45.228216 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.430651] k3s[841]: I0916 20:18:45.228254 841 legacy_serviceaccount_token_cleaner.go:103] "Starting legacy service account token cleaner controller" machine # [ 34.432343] k3s[841]: I0916 20:18:45.228269 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.433543] k3s[841]: I0916 20:18:45.228349 841 job_controller.go:254] "Starting job controller" machine # [ 34.434713] k3s[841]: I0916 20:18:45.228366 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.435915] k3s[841]: I0916 20:18:45.228406 841 horizontal.go:204] "Starting HPA controller" machine # [ 34.437123] k3s[841]: I0916 20:18:45.228422 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.438319] k3s[841]: I0916 20:18:45.228469 841 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-legacy-unknown" machine # [ 34.439984] k3s[841]: I0916 20:18:45.228486 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.441192] k3s[841]: I0916 20:18:45.228532 841 node_lifecycle_controller.go:453] "Sending events to api server" machine # [ 34.442517] k3s[841]: I0916 20:18:45.228559 841 node_lifecycle_controller.go:460] "Starting node controller" machine # [ 34.443801] k3s[841]: I0916 20:18:45.228570 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.445082] k3s[841]: I0916 20:18:45.228626 841 vac_protection_controller.go:206] "Starting VAC protection controller" machine # [ 34.446468] k3s[841]: I0916 20:18:45.228645 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.447668] k3s[841]: I0916 20:18:45.228672 841 ttlafterfinished_controller.go:112] "Starting TTL after finished controller" machine # [ 34.449219] k3s[841]: I0916 20:18:45.228691 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.450426] k3s[841]: I0916 20:18:45.228767 841 endpoints_controller.go:193] "Starting endpoint controller" machine # [ 34.451711] k3s[841]: I0916 20:18:45.228783 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.453003] k3s[841]: I0916 20:18:45.228848 841 stateful_set.go:180] "Starting stateful set controller" machine # [ 34.454238] k3s[841]: I0916 20:18:45.228862 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.455433] k3s[841]: I0916 20:18:45.228883 841 certificate_controller.go:120] "Starting certificate controller" name="csrapproving" machine # [ 34.457050] k3s[841]: I0916 20:18:45.228897 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.458240] k3s[841]: I0916 20:18:45.228937 841 cleaner.go:83] "Starting CSR cleaner controller" machine # [ 34.459388] k3s[841]: I0916 20:18:45.229005 841 expand_controller.go:328] "Starting expand controller" machine # [ 34.460666] k3s[841]: I0916 20:18:45.229021 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.461844] k3s[841]: I0916 20:18:45.229086 841 servicecidrs_controller.go:136] "Starting" controller="service-cidr-controller" machine # [ 34.463301] k3s[841]: I0916 20:18:45.229102 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.464551] k3s[841]: I0916 20:18:45.229144 841 disruption.go:458] "Sending events to api server." machine # [ 34.465829] k3s[841]: I0916 20:18:45.229196 841 disruption.go:465] "Starting disruption controller" machine # [ 34.467029] k3s[841]: I0916 20:18:45.229207 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.468238] k3s[841]: I0916 20:18:45.229292 841 pv_controller_base.go:307] "Starting persistent volume controller" machine # [ 34.469574] k3s[841]: I0916 20:18:45.229309 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.470763] k3s[841]: I0916 20:18:45.229340 841 pv_protection_controller.go:81] "Starting PV protection controller" machine # [ 34.472150] k3s[841]: I0916 20:18:45.229356 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.473360] k3s[841]: I0916 20:18:45.229770 841 garbagecollector.go:141] "Starting controller" controller="garbagecollector" machine # [ 34.474807] k3s[841]: I0916 20:18:45.229816 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.476050] k3s[841]: I0916 20:18:45.229886 841 resource_quota_controller.go:297] "Starting resource quota controller" machine # [ 34.477435] k3s[841]: I0916 20:18:45.229903 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.478641] k3s[841]: I0916 20:18:45.229944 841 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-serving" machine # [ 34.480364] k3s[841]: I0916 20:18:45.242065 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.481567] k3s[841]: I0916 20:18:45.242144 841 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-client" machine # [ 34.483202] k3s[841]: I0916 20:18:45.242159 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.484434] k3s[841]: I0916 20:18:45.242180 841 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kube-apiserver-client" machine # [ 34.486099] k3s[841]: I0916 20:18:45.242192 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.487252] k3s[841]: I0916 20:18:45.242220 841 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" machine # [ 34.489805] k3s[841]: I0916 20:18:45.242579 841 graph_builder.go:386] "Running" component="GraphBuilder" machine # [ 34.491002] k3s[841]: I0916 20:18:45.242621 841 resource_quota_monitor.go:309] "QuotaMonitor running" machine # [ 34.492189] k3s[841]: I0916 20:18:45.242831 841 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" machine # [ 34.494641] k3s[841]: I0916 20:18:45.243115 841 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" machine # [ 34.497210] k3s[841]: I0916 20:18:45.243225 841 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" machine # [ 34.499678] k3s[841]: I0916 20:18:45.270603 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.500962] k3s[841]: time="2026-09-16T20:18:45Z" 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=Normal machine # [ 34.504298] k3s[841]: I0916 20:18:45.306400 841 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" machine # [ 34.507487] k3s[841]: I0916 20:18:45.310211 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.508779] k3s[841]: I0916 20:18:45.334889 841 shared_informer.go:377] "Caches are synced" machine # [ 34.509878] k3s[841]: I0916 20:18:45.334970 841 range_allocator.go:177] "Sending events to api server" machine # [ 34.511087] k3s[841]: I0916 20:18:45.334996 841 range_allocator.go:181] "Starting range CIDR allocator" machine # [ 34.512359] k3s[841]: I0916 20:18:45.335003 841 shared_informer.go:370] "Waiting for caches to sync" machine # [ 34.513548] k3s[841]: I0916 20:18:45.335009 841 shared_informer.go:377] "Caches are synced" machine # [ 34.514651] k3s[841]: I0916 20:18:45.335369 841 shared_informer.go:377] "Caches are synced" machine # [ 34.515749] k3s[841]: I0916 20:18:45.336004 841 shared_informer.go:377] "Caches are synced" machine # [ 34.516927] k3s[841]: I0916 20:18:45.336026 841 shared_informer.go:377] "Caches are synced" machine # [ 34.518041] k3s[841]: I0916 20:18:45.336402 841 shared_informer.go:377] "Caches are synced" machine # [ 34.519142] k3s[841]: I0916 20:18:45.336495 841 shared_informer.go:377] "Caches are synced" machine # [ 34.520288] k3s[841]: I0916 20:18:45.362437 841 range_allocator.go:433] "Set node PodCIDR" node="machine" podCIDRs=["10.42.0.0/24"] machine # [ 34.544985] k3s[841]: I0916 20:18:45.426777 841 shared_informer.go:377] "Caches are synced" machine # [ 34.546539] k3s[841]: I0916 20:18:45.426877 841 shared_informer.go:377] "Caches are synced" machine # [ 34.548051] k3s[841]: I0916 20:18:45.428343 841 shared_informer.go:377] "Caches are synced" machine # [ 34.549512] k3s[841]: I0916 20:18:45.428399 841 shared_informer.go:377] "Caches are synced" machine # [ 34.550944] k3s[841]: I0916 20:18:45.428472 841 shared_informer.go:377] "Caches are synced" machine # [ 34.552417] k3s[841]: I0916 20:18:45.428536 841 shared_informer.go:377] "Caches are synced" machine # [ 34.553849] k3s[841]: I0916 20:18:45.428637 841 shared_informer.go:377] "Caches are synced" machine # [ 34.555290] k3s[841]: I0916 20:18:45.428688 841 shared_informer.go:377] "Caches are synced" machine # [ 34.556811] k3s[841]: I0916 20:18:45.428718 841 shared_informer.go:377] "Caches are synced" machine # [ 34.558251] k3s[841]: I0916 20:18:45.428766 841 shared_informer.go:377] "Caches are synced" machine # [ 34.559709] k3s[841]: I0916 20:18:45.428843 841 shared_informer.go:377] "Caches are synced" machine # [ 34.561236] k3s[841]: I0916 20:18:45.428905 841 shared_informer.go:377] "Caches are synced" machine # [ 34.562681] k3s[841]: I0916 20:18:45.428939 841 shared_informer.go:377] "Caches are synced" machine # [ 34.564164] k3s[841]: I0916 20:18:45.429037 841 shared_informer.go:377] "Caches are synced" machine # [ 34.565612] k3s[841]: I0916 20:18:45.429070 841 shared_informer.go:377] "Caches are synced" machine # [ 34.567049] k3s[841]: I0916 20:18:45.429119 841 shared_informer.go:377] "Caches are synced" machine # [ 34.568532] k3s[841]: I0916 20:18:45.429160 841 shared_informer.go:377] "Caches are synced" machine # [ 34.569983] k3s[841]: I0916 20:18:45.429515 841 shared_informer.go:377] "Caches are synced" machine # [ 34.571419] k3s[841]: I0916 20:18:45.429566 841 shared_informer.go:377] "Caches are synced" machine # [ 34.572964] k3s[841]: I0916 20:18:45.430237 841 shared_informer.go:377] "Caches are synced" machine # [ 34.574390] k3s[841]: I0916 20:18:45.430309 841 shared_informer.go:377] "Caches are synced" machine # [ 34.575808] k3s[841]: I0916 20:18:45.442893 841 shared_informer.go:377] "Caches are synced" machine # [ 34.577316] k3s[841]: I0916 20:18:45.442946 841 shared_informer.go:377] "Caches are synced" machine # [ 34.578736] k3s[841]: I0916 20:18:45.443037 841 shared_informer.go:377] "Caches are synced" machine # [ 34.600094] k3s[841]: time="2026-09-16T20:18:45Z" 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=Normal machine # [ 34.629280] k3s[841]: I0916 20:18:45.511159 841 controller.go:667] quota admission added evaluator for: jobs.batch machine # [ 34.642657] k3s[841]: time="2026-09-16T20:18:45Z" 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=Normal machine # [ 34.652178] k3s[841]: I0916 20:18:45.528238 841 shared_informer.go:377] "Caches are synced" machine # [ 34.653372] k3s[841]: I0916 20:18:45.528329 841 shared_informer.go:377] "Caches are synced" machine # [ 34.654494] k3s[841]: I0916 20:18:45.528473 841 shared_informer.go:377] "Caches are synced" machine # [ 34.655600] k3s[841]: I0916 20:18:45.528611 841 shared_informer.go:377] "Caches are synced" machine # [ 34.656816] k3s[841]: I0916 20:18:45.528701 841 node_lifecycle_controller.go:1234] "Initializing eviction metric for zone" zone="" machine # [ 34.658316] k3s[841]: I0916 20:18:45.528783 841 node_lifecycle_controller.go:886] "Missing timestamp for Node. Assuming now as a timestamp" node="machine" machine # [ 34.664111] k3s[841]: I0916 20:18:45.528819 841 shared_informer.go:377] "Caches are synced" machine # [ 34.665328] k3s[841]: I0916 20:18:45.529205 841 shared_informer.go:377] "Caches are synced" machine # [ 34.666496] k3s[841]: I0916 20:18:45.529255 841 shared_informer.go:377] "Caches are synced" machine # [ 34.667677] k3s[841]: I0916 20:18:45.529277 841 shared_informer.go:377] "Caches are synced" machine # [ 34.669117] k3s[841]: I0916 20:18:45.529379 841 shared_informer.go:377] "Caches are synced" machine # [ 34.670446] k3s[841]: I0916 20:18:45.529397 841 shared_informer.go:377] "Caches are synced" machine # [ 34.671535] k3s[841]: I0916 20:18:45.529883 841 node_lifecycle_controller.go:1080] "Controller detected that zone is now in new state" zone="" newState="Normal" machine # [ 34.673813] k3s[841]: I0916 20:18:45.529957 841 shared_informer.go:377] "Caches are synced" machine # [ 34.686453] k3s[841]: time="2026-09-16T20:18:45Z" 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=Normal machine # [ 34.690135] k3s[841]: I0916 20:18:45.571551 841 shared_informer.go:377] "Caches are synced" machine # [ 35.069803] k3s[841]: I0916 20:18:45.950500 841 controller.go:667] quota admission added evaluator for: replicasets.apps machine # [ 35.127239] k3s[841]: I0916 20:18:46.009081 841 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/16 machine # [ 35.138281] k3s[841]: I0916 20:18:46.019834 841 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/16 machine # [ 35.168108] k3s[841]: time="2026-09-16T20:18:46Z" 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=Normal machine # [ 35.318688] k3s[841]: time="2026-09-16T20:18:46Z" level=info msg="Flannel found PodCIDR assigned for node machine" machine # [ 35.330163] k3s[841]: time="2026-09-16T20:18:46Z" 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=Normal machine # [ 35.339332] k3s[841]: time="2026-09-16T20:18:46Z" level=info msg="The interface eth0 with ipv4 address 10.0.2.15 will be used by flannel" machine # [ 35.345423] k3s[841]: I0916 20:18:46.215777 841 kube.go:139] Waiting 10m0s for node controller to sync machine # [ 35.350184] k3s[841]: I0916 20:18:46.215966 841 kube.go:537] Starting kube subnet manager machine # [ 35.360104] k3s[841]: time="2026-09-16T20:18:46Z" 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=Normal machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 35.589046] k3s[841]: time="2026-09-16T20:18:46Z" level=info msg="Tunnel authorizer set Kubelet Port 0.0.0.0:10250" machine # [ 36.032287] k3s[841]: I0916 20:18:46.911984 841 shared_informer.go:377] "Caches are synced" machine # [ 36.048598] k3s[841]: I0916 20:18:46.930409 841 shared_informer.go:377] "Caches are synced" machine # [ 36.056559] k3s[841]: I0916 20:18:46.934094 841 garbagecollector.go:166] "Garbage collector: all resource monitors have synced" machine # [ 36.061578] k3s[841]: I0916 20:18:46.934143 841 garbagecollector.go:169] "Proceeding to collect garbage" machine # [ 36.112031] systemd[1]: Created slice libcontainer container kubepods-burstable-pode04c883d_7e10_4fa9_8c32_be5b058ac4ac.slice. machine # [ 36.153090] systemd[1]: Created slice libcontainer container kubepods-burstable-podc214424f_6f1b_4928_ab44_d29569d84105.slice. machine # [ 36.224223] k3s[841]: I0916 20:18:47.104194 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"config-volume\" (UniqueName: \"kubernetes.io/configmap/e04c883d-7e10-4fa9-8c32-be5b058ac4ac-config-volume\") pod \"coredns-c5fdd76cf-zlpb9\" (UID: \"e04c883d-7e10-4fa9-8c32-be5b058ac4ac\") " pod="kube-system/coredns-c5fdd76cf-zlpb9" machine # [ 36.237260] k3s[841]: I0916 20:18:47.104343 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-config\") pod \"helm-install-niks3-kq6ks\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.249539] k3s[841]: I0916 20:18:47.104423 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"custom-config-volume\" (UniqueName: \"kubernetes.io/configmap/e04c883d-7e10-4fa9-8c32-be5b058ac4ac-custom-config-volume\") pod \"coredns-c5fdd76cf-zlpb9\" (UID: \"e04c883d-7e10-4fa9-8c32-be5b058ac4ac\") " pod="kube-system/coredns-c5fdd76cf-zlpb9" machine # [ 36.259672] k3s[841]: I0916 20:18:47.104486 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-tpprp\" (UniqueName: \"kubernetes.io/projected/e04c883d-7e10-4fa9-8c32-be5b058ac4ac-kube-api-access-tpprp\") pod \"coredns-c5fdd76cf-zlpb9\" (UID: \"e04c883d-7e10-4fa9-8c32-be5b058ac4ac\") " pod="kube-system/coredns-c5fdd76cf-zlpb9" machine # [ 36.268441] k3s[841]: I0916 20:18:47.104540 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-helm\") pod \"helm-install-niks3-kq6ks\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.275790] k3s[841]: I0916 20:18:47.104588 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-cache\") pod \"helm-install-niks3-kq6ks\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.282679] k3s[841]: I0916 20:18:47.104633 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-tmp\") pod \"helm-install-niks3-kq6ks\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.288741] k3s[841]: I0916 20:18:47.104682 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"values\" (UniqueName: \"kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-values\") pod \"helm-install-niks3-kq6ks\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.294326] k3s[841]: I0916 20:18:47.104726 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"content\" (UniqueName: \"kubernetes.io/configmap/c214424f-6f1b-4928-ab44-d29569d84105-content\") pod \"helm-install-niks3-kq6ks\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.299746] k3s[841]: I0916 20:18:47.104777 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-c2tmb\" (UniqueName: \"kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-kube-api-access-c2tmb\") pod \"helm-install-niks3-kq6ks\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.348368] k3s[841]: I0916 20:18:47.228595 841 kube.go:163] Node controller sync successful machine # [ 36.351164] k3s[841]: I0916 20:18:47.228775 841 vxlan.go:128] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false machine # [ 36.391226] k3s[841]: I0916 20:18:47.272317 841 kube.go:704] List of node(machine) annotations: map[string]string{"alpha.kubernetes.io/provided-node-ip":"10.0.2.15,fec0::9a9d:43f9:43e1:fefd", "k3s.io/hostname":"machine", "k3s.io/internal-ip":"10.0.2.15,fec0::9a9d:43f9:43e1:fefd", "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"} machine # [ 36.456795] (udev-worker)[1178]: Network interface NamePolicy= disabled on kernel command line. machine # [ 36.477410] k3s[841]: I0916 20:18:47.359157 841 iptables.go:50] Starting flannel in iptables mode... machine # [ 36.480875] k3s[841]: time="2026-09-16T20:18:47Z" level=warning msg="no subnet found for key: FLANNEL_NETWORK in file: /run/flannel/subnet.env" machine # [ 36.485476] k3s[841]: time="2026-09-16T20:18:47Z" level=warning msg="no subnet found for key: FLANNEL_SUBNET in file: /run/flannel/subnet.env" machine # [ 36.489358] k3s[841]: time="2026-09-16T20:18:47Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_NETWORK in file: /run/flannel/subnet.env" machine # [ 36.491687] k3s[841]: time="2026-09-16T20:18:47Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_SUBNET in file: /run/flannel/subnet.env" machine # [ 36.496909] k3s[841]: I0916 20:18:47.364408 841 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 rules machine # [ 36.501933] k3s[841]: I0916 20:18:47.370999 841 kube.go:558] Creating the node lease for IPv4. This is the n.Spec.PodCIDRs: [10.42.0.0/24] machine # [ 36.542550] dhcpcd[627]: flannel.1: IAID 37:93:65:f8 machine # [ 36.544881] dhcpcd[627]: flannel.1: adding address fe80::1059:37ff:fe93:65f8 machine # [ 36.620833] k3s[841]: E0916 20:18:47.502554 841 log.go:32] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"4933f468ba62c5640a5c39b114a49d6135a81ca105ccac0fa54c0f206b036681\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" machine # [ 36.627351] k3s[841]: E0916 20:18:47.502721 841 kuberuntime_sandbox.go:71] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"4933f468ba62c5640a5c39b114a49d6135a81ca105ccac0fa54c0f206b036681\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.634055] k3s[841]: E0916 20:18:47.502759 841 kuberuntime_manager.go:1568] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"4933f468ba62c5640a5c39b114a49d6135a81ca105ccac0fa54c0f206b036681\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-kq6ks" machine # [ 36.642763] k3s[841]: E0916 20:18:47.502864 841 pod_workers.go:1324] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"helm-install-niks3-kq6ks_kube-system(c214424f-6f1b-4928-ab44-d29569d84105)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"helm-install-niks3-kq6ks_kube-system(c214424f-6f1b-4928-ab44-d29569d84105)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"4933f468ba62c5640a5c39b114a49d6135a81ca105ccac0fa54c0f206b036681\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/helm-install-niks3-kq6ks" podUID="c214424f-6f1b-4928-ab44-d29569d84105" machine # [ 36.660173] k3s[841]: E0916 20:18:47.539156 841 log.go:32] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"9e88fac8a2306f0f37a7895fa5e44da5a75e6c9268f5880cdc5a970fb6c52754\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" machine # [ 36.664728] k3s[841]: E0916 20:18:47.539233 841 kuberuntime_sandbox.go:71] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"9e88fac8a2306f0f37a7895fa5e44da5a75e6c9268f5880cdc5a970fb6c52754\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-c5fdd76cf-zlpb9" machine # [ 36.670738] k3s[841]: E0916 20:18:47.539255 841 kuberuntime_manager.go:1568] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"9e88fac8a2306f0f37a7895fa5e44da5a75e6c9268f5880cdc5a970fb6c52754\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-c5fdd76cf-zlpb9" machine # [ 36.675948] k3s[841]: E0916 20:18:47.539324 841 pod_workers.go:1324] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"coredns-c5fdd76cf-zlpb9_kube-system(e04c883d-7e10-4fa9-8c32-be5b058ac4ac)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"coredns-c5fdd76cf-zlpb9_kube-system(e04c883d-7e10-4fa9-8c32-be5b058ac4ac)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"9e88fac8a2306f0f37a7895fa5e44da5a75e6c9268f5880cdc5a970fb6c52754\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/coredns-c5fdd76cf-zlpb9" podUID="e04c883d-7e10-4fa9-8c32-be5b058ac4ac" machine # [ 36.707259] k3s[841]: I0916 20:18:47.589030 841 iptables.go:111] Setting up masking rules machine # [ 36.723608] dhcpcd[627]: flannel.1: soliciting a DHCP lease machine # [ 36.734212] k3s[841]: I0916 20:18:47.616048 841 iptables.go:212] Changing default FORWARD chain policy to ACCEPT machine # [ 36.746803] k3s[841]: time="2026-09-16T20:18:47Z" level=info msg="Wrote flannel subnet file to /run/flannel/subnet.env" machine # [ 36.748667] k3s[841]: time="2026-09-16T20:18:47Z" level=info msg="Running flannel backend" machine # [ 36.750994] k3s[841]: I0916 20:18:47.630321 841 vxlan_network.go:68] watching for new subnet leases machine # [ 36.752876] k3s[841]: I0916 20:18:47.630346 841 vxlan_network.go:115] starting vxlan device watcher machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 36.820766] k3s[841]: I0916 20:18:47.702630 841 iptables.go:358] bootstrap done machine # [ 36.856821] k3s[841]: I0916 20:18:47.738677 841 iptables.go:358] bootstrap done machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 38.593198] k3s[841]: time="2026-09-16T20:18:49Z" level=info msg="Started tunnel to 10.0.2.15:6443" machine # [ 38.597295] k3s[841]: time="2026-09-16T20:18:49Z" level=info msg="Stopped tunnel to 127.0.0.1:6443" machine # [ 38.601140] k3s[841]: time="2026-09-16T20:18:49Z" level=info msg="Connecting to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect" machine # [ 38.605915] k3s[841]: time="2026-09-16T20:18:49Z" level=info msg="Proxy done" err="context canceled" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 38.611011] k3s[841]: time="2026-09-16T20:18:49Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF" machine # [ 38.616778] k3s[841]: time="2026-09-16T20:18:49Z" level=info msg="Handling backend connection request [machine]" machine # [ 38.621897] k3s[841]: time="2026-09-16T20:18:49Z" level=info msg="Connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect" machine # [ 38.626667] k3s[841]: time="2026-09-16T20:18:49Z" level=info msg="Remotedialer connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect" machine # [ 38.646527] dhcpcd[627]: flannel.1: soliciting an IPv6 router machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 40.310274] k3s[841]: I0916 20:18:51.190884 841 kuberuntime_manager.go:2095] "Updating runtime config through cri with podcidr" CIDR="10.42.0.0/24" machine # [ 40.316494] k3s[841]: I0916 20:18:51.198261 841 kubelet_network.go:47] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="10.42.0.0/24" machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 41.491469] k3s[841]: time="2026-09-16T20:18:52Z" level=info msg="Starting network policy controller version v2.6.3-k3s1, built on 1970-01-01T01:01:01Z, go1.26.7" machine # [ 41.491827] k3s[841]: I0916 20:18:52.372251 841 network_policy_controller.go:164] Starting network policy controller machine # [ 41.724552] dhcpcd[627]: flannel.1: probing for an IPv4LL address machine # [ 41.738400] k3s[841]: I0916 20:18:52.620294 841 network_policy_controller.go:179] Starting network policy controller full sync goroutine machine # Error from server (NotFound): namespaces "niks3" not found machine # Error from server (NotFound): namespaces "niks3" not found machine # Error from server (NotFound): namespaces "niks3" not found machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 46.574449] dhcpcd[627]: flannel.1: using IPv4LL address 169.254.184.99 machine # [ 46.574813] dhcpcd[627]: flannel.1: adding route to 169.254.0.0/16 machine # Error from server (NotFound): namespaces "niks3" not found machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 49.038936] cni0: port 1(vethb19643de) entered blocking state machine # [ 49.039073] cni0: port 1(vethb19643de) entered disabled state machine # [ 49.039180] vethb19643de: entered allmulticast mode machine # [ 49.039387] vethb19643de: entered promiscuous mode machine # [ 49.071656] cni0: port 1(vethb19643de) entered blocking state machine # [ 49.071741] cni0: port 1(vethb19643de) entered forwarding state machine # [ 49.135251] (udev-worker)[1579]: Network interface NamePolicy= disabled on kernel command line. machine # [ 49.139011] (udev-worker)[1581]: Network interface NamePolicy= disabled on kernel command line. machine # [ 49.167203] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount3620436430.mount: Deactivated successfully. machine # [ 49.195972] dhcpcd[627]: vethb19643de: IAID e5:78:22:e5 machine # [ 49.197259] dhcpcd[627]: vethb19643de: adding address fe80::c877:e5ff:fe78:22e5 machine # [ 49.264617] systemd[1]: Started libcontainer container 8819b5b15d53ccf93770e94e724ddf022f52466cbe34446ae8b7511a8453b751. machine # [ 49.521143] dhcpcd[627]: vethb19643de: soliciting a DHCP lease machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 50.022768] cni0: port 2(veth98adef0e) entered blocking state machine # [ 50.022854] cni0: port 2(veth98adef0e) entered disabled state machine # [ 50.022956] veth98adef0e: entered allmulticast mode machine # [ 50.023159] veth98adef0e: entered promiscuous mode machine # [ 50.074370] cni0: port 2(veth98adef0e) entered blocking state machine # [ 50.074431] cni0: port 2(veth98adef0e) entered forwarding state machine # [ 50.105616] dhcpcd[627]: veth98adef0e: waiting for carrier machine # [ 50.106496] dhcpcd[627]: veth98adef0e: carrier acquired machine # [ 50.118782] dhcpcd[627]: veth98adef0e: IAID 96:47:37:05 machine # [ 50.120145] dhcpcd[627]: veth98adef0e: adding address fe80::84fa:96ff:fe47:3705 machine # [ 50.148547] systemd[1]: Started libcontainer container 2de7110bbf1b1cdb02b11b8a704d5418780f12f5ae4e4007ce05a23efc084e48. machine # [ 50.212877] systemd[1]: Started libcontainer container 3730e21c3f81f5103bf8d9bba726af52a1c8c275ecfbfeb960336c935019f7c4. machine # [ 50.648866] dhcpcd[627]: flannel.1: no IPv6 Routers available machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 51.009295] dhcpcd[627]: vethb19643de: soliciting an IPv6 router machine # [ 51.107849] k3s[841]: I0916 20:19:01.989013 841 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/coredns-c5fdd76cf-zlpb9" podStartSLOduration=15.98898342 podStartE2EDuration="15.98898342s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-16 20:18:46 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-16 20:19:01.97620992 +0000 UTC m=+31.300781161" watchObservedRunningTime="2026-09-16 20:19:01.98898342 +0000 UTC m=+31.313554661" machine # [ 51.302543] dhcpcd[627]: veth98adef0e: soliciting a DHCP lease machine # [ 51.645251] systemd[1]: Started libcontainer container 9f6082ceb69b81bdc390ebe7916f449149a17f1602d5a11a7107f534658b5979. machine # [ 52.174808] k3s[841]: I0916 20:19:03.052485 841 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/helm-install-niks3-kq6ks" podStartSLOduration=17.0524622 podStartE2EDuration="17.0524622s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-16 20:18:46 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-16 20:19:03.01660892 +0000 UTC m=+32.341180201" watchObservedRunningTime="2026-09-16 20:19:03.0524622 +0000 UTC m=+32.377033761" machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 52.458568] dhcpcd[627]: veth98adef0e: soliciting an IPv6 router machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 53.879476] k3s[841]: I0916 20:19:04.760626 841 alloc.go:329] "allocated clusterIPs" service="niks3/niks3" clusterIPs={"IPv4":"10.43.62.216"} machine # [ 53.920081] k3s[841]: I0916 20:19:04.798126 841 controller.go:667] quota admission added evaluator for: cronjobs.batch machine # [ 53.944924] systemd[1]: cri-containerd-9f6082ceb69b81bdc390ebe7916f449149a17f1602d5a11a7107f534658b5979.scope: Deactivated successfully. machine # [ 53.948147] systemd[1]: cri-containerd-9f6082ceb69b81bdc390ebe7916f449149a17f1602d5a11a7107f534658b5979.scope: Consumed 950ms CPU time over 2.302s wall clock time, 38M memory peak, 4.1M incoming IP traffic, 77.6K outgoing IP traffic. machine # [ 54.005856] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-9f6082ceb69b81bdc390ebe7916f449149a17f1602d5a11a7107f534658b5979-rootfs.mount: Deactivated successfully. machine # [ 54.032822] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod84f8fca6_03c4_429a_b6c5_20051fa070a9.slice. machine # [ 54.078469] k3s[841]: I0916 20:19:04.960326 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"db\" (UniqueName: \"kubernetes.io/secret/84f8fca6-03c4-429a-b6c5-20051fa070a9-db\") pod \"niks3-5c78d87487-h89mh\" (UID: \"84f8fca6-03c4-429a-b6c5-20051fa070a9\") " pod="niks3/niks3-5c78d87487-h89mh" machine # [ 54.083181] k3s[841]: I0916 20:19:04.961288 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"s3\" (UniqueName: \"kubernetes.io/secret/84f8fca6-03c4-429a-b6c5-20051fa070a9-s3\") pod \"niks3-5c78d87487-h89mh\" (UID: \"84f8fca6-03c4-429a-b6c5-20051fa070a9\") " pod="niks3/niks3-5c78d87487-h89mh" machine # [ 54.087349] k3s[841]: I0916 20:19:04.961342 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"oidc\" (UniqueName: \"kubernetes.io/configmap/84f8fca6-03c4-429a-b6c5-20051fa070a9-oidc\") pod \"niks3-5c78d87487-h89mh\" (UID: \"84f8fca6-03c4-429a-b6c5-20051fa070a9\") " pod="niks3/niks3-5c78d87487-h89mh" machine # [ 54.091453] k3s[841]: I0916 20:19:04.961382 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-777wz\" (UniqueName: \"kubernetes.io/projected/84f8fca6-03c4-429a-b6c5-20051fa070a9-kube-api-access-777wz\") pod \"niks3-5c78d87487-h89mh\" (UID: \"84f8fca6-03c4-429a-b6c5-20051fa070a9\") " pod="niks3/niks3-5c78d87487-h89mh" machine # [ 54.096557] k3s[841]: I0916 20:19:04.961406 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/84f8fca6-03c4-429a-b6c5-20051fa070a9-token\") pod \"niks3-5c78d87487-h89mh\" (UID: \"84f8fca6-03c4-429a-b6c5-20051fa070a9\") " pod="niks3/niks3-5c78d87487-h89mh" machine # [ 54.392135] cni0: port 3(veth4acc9f1a) entered blocking state machine # [ 54.392206] cni0: port 3(veth4acc9f1a) entered disabled state machine # [ 54.392262] veth4acc9f1a: entered allmulticast mode machine # [ 54.392408] veth4acc9f1a: entered promiscuous mode machine # [ 54.412360] cni0: port 3(veth4acc9f1a) entered blocking state machine # [ 54.412450] cni0: port 3(veth4acc9f1a) entered forwarding state machine # [ 54.467918] (udev-worker)[2063]: Network interface NamePolicy= disabled on kernel command line. machine # [ 54.506713] dhcpcd[627]: veth4acc9f1a: IAID e8:68:0c:21 machine # [ 54.508307] dhcpcd[627]: veth4acc9f1a: adding address fe80::4840:e8ff:fe68:c21 machine # [ 54.522050] dhcpcd[627]: vethb19643de: probing for an IPv4LL address machine # [ 54.536775] systemd[1]: Started libcontainer container 9d01645a878dc46585509020b0018be3aaaa8b392cc75b390a4d585737e7b2d7. machine # [ 55.104792] systemd[1]: Started libcontainer container ee75ce3065bcb9f6367269fa63c7a8435c83decf969aa38da5f7cbe392d3299a. machine # [ 55.138705] systemd[1]: cri-containerd-3730e21c3f81f5103bf8d9bba726af52a1c8c275ecfbfeb960336c935019f7c4.scope: Deactivated successfully. machine # [ 55.189988] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-3730e21c3f81f5103bf8d9bba726af52a1c8c275ecfbfeb960336c935019f7c4-rootfs.mount: Deactivated successfully. machine # [ 55.226741] postgres[2183]: [2183] ERROR: relation "goose_db_version" does not exist at character 36 machine # [ 55.229113] postgres[2183]: [2183] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC machine # [ 55.339684] cni0: port 2(veth98adef0e) entered disabled state machine # [ 55.342148] veth98adef0e (unregistering): left allmulticast mode machine # [ 55.342191] veth98adef0e (unregistering): left promiscuous mode machine # [ 55.342218] cni0: port 2(veth98adef0e) entered disabled state machine # [ 55.337584] dhcpcd[627]: veth98adef0e: carrier lost machine # [ 55.382194] dhcpcd[627]: veth98adef0e: deleting address fe80::84fa:96ff:fe47:3705 machine # [ 55.432406] dhcpcd[627]: veth98adef0e: removing interface machine # [ 55.490245] k3s[841]: I0916 20:19:06.371668 841 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/configmap/c214424f-6f1b-4928-ab44-d29569d84105-content\" (UniqueName: \"kubernetes.io/configmap/c214424f-6f1b-4928-ab44-d29569d84105-content\") pod \"c214424f-6f1b-4928-ab44-d29569d84105\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " machine # [ 55.494844] k3s[841]: I0916 20:19:06.371715 841 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-values\" (UniqueName: \"kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-values\") pod \"c214424f-6f1b-4928-ab44-d29569d84105\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " machine # [ 55.499236] k3s[841]: I0916 20:19:06.371737 841 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-cache\") pod \"c214424f-6f1b-4928-ab44-d29569d84105\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " machine # [ 55.503826] k3s[841]: I0916 20:19:06.371762 841 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-helm\") pod \"c214424f-6f1b-4928-ab44-d29569d84105\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " machine # [ 55.508470] k3s[841]: I0916 20:19:06.371784 841 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-kube-api-access-c2tmb\" (UniqueName: \"kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-kube-api-access-c2tmb\") pod \"c214424f-6f1b-4928-ab44-d29569d84105\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " machine # [ 55.512881] k3s[841]: I0916 20:19:06.371806 841 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-tmp\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-tmp\") pod \"c214424f-6f1b-4928-ab44-d29569d84105\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " machine # [ 55.517948] k3s[841]: I0916 20:19:06.371825 841 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-config\") pod \"c214424f-6f1b-4928-ab44-d29569d84105\" (UID: \"c214424f-6f1b-4928-ab44-d29569d84105\") " machine # [ 55.523054] k3s[841]: I0916 20:19:06.395674 841 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/configmap/c214424f-6f1b-4928-ab44-d29569d84105-content" pod "c214424f-6f1b-4928-ab44-d29569d84105" (UID: "c214424f-6f1b-4928-ab44-d29569d84105"). InnerVolumeSpecName "content". PluginName "kubernetes.io/configmap", VolumeGIDValue "" machine # [ 55.532444] k3s[841]: I0916 20:19:06.414288 841 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-cache" pod "c214424f-6f1b-4928-ab44-d29569d84105" (UID: "c214424f-6f1b-4928-ab44-d29569d84105"). InnerVolumeSpecName "klipper-cache". PluginName "kubernetes.io/empty-dir", VolumeGIDValue "" machine # [ 55.538961] k3s[841]: I0916 20:19:06.420834 841 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-config" pod "c214424f-6f1b-4928-ab44-d29569d84105" (UID: "c214424f-6f1b-4928-ab44-d29569d84105"). InnerVolumeSpecName "klipper-config". PluginName "kubernetes.io/empty-dir", VolumeGIDValue "" machine # [ 55.543684] k3s[841]: I0916 20:19:06.425552 841 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-tmp" pod "c214424f-6f1b-4928-ab44-d29569d84105" (UID: "c214424f-6f1b-4928-ab44-d29569d84105"). InnerVolumeSpecName "tmp". PluginName "kubernetes.io/empty-dir", VolumeGIDValue "" machine # [ 55.547987] k3s[841]: I0916 20:19:06.425582 841 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-kube-api-access-c2tmb" pod "c214424f-6f1b-4928-ab44-d29569d84105" (UID: "c214424f-6f1b-4928-ab44-d29569d84105"). InnerVolumeSpecName "kube-api-access-c2tmb". PluginName "kubernetes.io/projected", VolumeGIDValue "" machine # [ 55.552566] k3s[841]: I0916 20:19:06.425700 841 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-values" pod "c214424f-6f1b-4928-ab44-d29569d84105" (UID: "c214424f-6f1b-4928-ab44-d29569d84105"). InnerVolumeSpecName "values". PluginName "kubernetes.io/projected", VolumeGIDValue "" machine # [ 55.557109] k3s[841]: I0916 20:19:06.439002 841 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-helm" pod "c214424f-6f1b-4928-ab44-d29569d84105" (UID: "c214424f-6f1b-4928-ab44-d29569d84105"). InnerVolumeSpecName "klipper-helm". PluginName "kubernetes.io/empty-dir", VolumeGIDValue "" machine # [ 55.590193] k3s[841]: I0916 20:19:06.472096 841 reconciler_common.go:299] "Volume detached for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-cache\") on node \"machine\" DevicePath \"\"" machine # [ 55.594480] k3s[841]: I0916 20:19:06.476207 841 reconciler_common.go:299] "Volume detached for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-helm\") on node \"machine\" DevicePath \"\"" machine # [ 55.597430] k3s[841]: I0916 20:19:06.476233 841 reconciler_common.go:299] "Volume detached for volume \"kube-api-access-c2tmb\" (UniqueName: \"kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-kube-api-access-c2tmb\") on node \"machine\" DevicePath \"\"" machine # [ 55.600467] k3s[841]: I0916 20:19:06.476256 841 reconciler_common.go:299] "Volume detached for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-tmp\") on node \"machine\" DevicePath \"\"" machine # [ 55.603074] k3s[841]: I0916 20:19:06.476284 841 reconciler_common.go:299] "Volume detached for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/c214424f-6f1b-4928-ab44-d29569d84105-klipper-config\") on node \"machine\" DevicePath \"\"" machine # [ 55.606054] k3s[841]: I0916 20:19:06.476294 841 reconciler_common.go:299] "Volume detached for volume \"content\" (UniqueName: \"kubernetes.io/configmap/c214424f-6f1b-4928-ab44-d29569d84105-content\") on node \"machine\" DevicePath \"\"" machine # [ 55.608759] k3s[841]: I0916 20:19:06.476304 841 reconciler_common.go:299] "Volume detached for volume \"values\" (UniqueName: \"kubernetes.io/projected/c214424f-6f1b-4928-ab44-d29569d84105-values\") on node \"machine\" DevicePath \"\"" machine # [ 55.983839] systemd[1]: Removed slice libcontainer container kubepods-burstable-podc214424f_6f1b_4928_ab44_d29569d84105.slice. machine # [ 55.989109] systemd[1]: kubepods-burstable-podc214424f_6f1b_4928_ab44_d29569d84105.slice: Consumed 974ms CPU time over 19.828s wall clock time, 38.4M memory peak, 4.1M incoming IP traffic, 77.6K outgoing IP traffic. machine # [ 55.998657] dhcpcd[627]: veth4acc9f1a: soliciting a DHCP lease machine # [ 56.007965] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-3730e21c3f81f5103bf8d9bba726af52a1c8c275ecfbfeb960336c935019f7c4-shm.mount: Deactivated successfully. machine # [ 56.015325] systemd[1]: run-netns-cni\x2d984f5221\x2da5b1\x2d12a6\x2d40a5\x2d7b838d5a7180.mount: Deactivated successfully. machine # [ 56.020234] systemd[1]: var-lib-kubelet-pods-c214424f\x2d6f1b\x2d4928\x2dab44\x2dd29569d84105-volumes-kubernetes.io\x7eprojected-kube\x2dapi\x2daccess\x2dc2tmb.mount: Deactivated successfully. machine # [ 56.026669] systemd[1]: var-lib-kubelet-pods-c214424f\x2d6f1b\x2d4928\x2dab44\x2dd29569d84105-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dcache.mount: Deactivated successfully. machine # [ 56.033250] systemd[1]: var-lib-kubelet-pods-c214424f\x2d6f1b\x2d4928\x2dab44\x2dd29569d84105-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dhelm.mount: Deactivated successfully. machine # [ 56.038480] systemd[1]: var-lib-kubelet-pods-c214424f\x2d6f1b\x2d4928\x2dab44\x2dd29569d84105-volumes-kubernetes.io\x7eprojected-values.mount: Deactivated successfully. machine # [ 56.043094] systemd[1]: var-lib-kubelet-pods-c214424f\x2d6f1b\x2d4928\x2dab44\x2dd29569d84105-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dconfig.mount: Deactivated successfully. machine # [ 56.047744] systemd[1]: var-lib-kubelet-pods-c214424f\x2d6f1b\x2d4928\x2dab44\x2dd29569d84105-volumes-kubernetes.io\x7eempty\x2ddir-tmp.mount: Deactivated successfully. machine # [ 56.132643] k3s[841]: I0916 20:19:07.013355 841 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="3730e21c3f81f5103bf8d9bba726af52a1c8c275ecfbfeb960336c935019f7c4" machine # [ 56.175560] k3s[841]: I0916 20:19:07.057000 841 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/niks3-5c78d87487-h89mh" podStartSLOduration=3.05696362 podStartE2EDuration="3.05696362s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-16 20:19:04 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-16 20:19:07.05611548 +0000 UTC m=+36.380686741" watchObservedRunningTime="2026-09-16 20:19:07.05696362 +0000 UTC m=+36.381534881" machine # [ 56.234874] dhcpcd[627]: veth4acc9f1a: soliciting an IPv6 router machine # [ 59.665743] dhcpcd[627]: vethb19643de: using IPv4LL address 169.254.246.165 machine # [ 59.666184] dhcpcd[627]: vethb19643de: adding route to 169.254.0.0/16 machine: (finished: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s, in 30.24 seconds) machine: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true machine: (finished: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true, in 0.52 seconds) machine: waiting for success: curl -sf http://localhost:30051/readyz | grep OK machine: (finished: waiting for success: curl -sf http://localhost:30051/readyz | grep OK, in 0.10 seconds) (finished: subtest: chart deploys and becomes ready, in 30.86 seconds) machine: waiting for success: kubectl -n ci get sa builder machine # [ 61.000699] dhcpcd[627]: veth4acc9f1a: probing for an IPv4LL address machine: (finished: waiting for success: kubectl -n ci get sa builder, in 0.34 seconds) machine: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt machine: (finished: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt, in 0.36 seconds) machine: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt machine: (finished: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt, in 0.34 seconds) machine: must succeed: readlink -f /run/current-system/sw/bin/niks3 machine: (finished: must succeed: readlink -f /run/current-system/sw/bin/niks3, in 0.03 seconds) subtest: allowed service account can push via workload identity machine: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/vl8mv2wi47vcylgmn3yzi4kyj5iqqchw-niks3-1.11.0 2>&1 machine # [ 63.015356] dhcpcd[627]: vethb19643de: no IPv6 Routers available machine: (finished: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/vl8mv2wi47vcylgmn3yzi4kyj5iqqchw-niks3-1.11.0 2>&1, in 2.01 seconds) machine: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/vl8mv2wi47vcylgmn3yzi4kyj5iqqchw.narinfo machine: (finished: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/vl8mv2wi47vcylgmn3yzi4kyj5iqqchw.narinfo, in 0.03 seconds) (finished: subtest: allowed service account can push via workload identity, in 2.04 seconds) subtest: write scope does not grant admin machine: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status machine: (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) (finished: subtest: write scope does not grant admin, in 0.03 seconds) subtest: other service accounts are rejected machine: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/vl8mv2wi47vcylgmn3yzi4kyj5iqqchw-niks3-1.11.0 2>&1 machine: (finished: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/vl8mv2wi47vcylgmn3yzi4kyj5iqqchw-niks3-1.11.0 2>&1, in 0.13 seconds) (finished: subtest: other service accounts are rejected, in 0.13 seconds) subtest: gc cronjob runs against the service machine: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual machine: (finished: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual, in 0.20 seconds) machine: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s machine # [ 64.446143] systemd[1]: Created slice libcontainer container kubepods-besteffort-podc9b6cea6_b4a7_4f59_93ee_de241fc708c4.slice. machine # [ 64.612914] k3s[841]: I0916 20:19:15.494312 841 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/c9b6cea6-b4a7-4f59-93ee-de241fc708c4-token\") pod \"gc-manual-xwnjr\" (UID: \"c9b6cea6-b4a7-4f59-93ee-de241fc708c4\") " pod="niks3/gc-manual-xwnjr" machine # [ 64.849907] cni0: port 2(veth62d1253d) entered blocking state machine # [ 64.849971] cni0: port 2(veth62d1253d) entered disabled state machine # [ 64.850033] veth62d1253d: entered allmulticast mode machine # [ 64.850146] veth62d1253d: entered promiscuous mode machine # [ 64.862890] cni0: port 2(veth62d1253d) entered blocking state machine # [ 64.862943] cni0: port 2(veth62d1253d) entered forwarding state machine # [ 64.902698] (udev-worker)[2558]: Network interface NamePolicy= disabled on kernel command line. machine # [ 64.947223] dhcpcd[627]: veth62d1253d: IAID c7:ed:98:95 machine # [ 64.948158] dhcpcd[627]: veth62d1253d: adding address fe80::4cfa:c7ff:feed:9895 machine # [ 64.972461] systemd[1]: Started libcontainer container 8a96748096812b7e95efca4f76161e02ae242758dd1e198d1d59ef381126c6f6. machine # [ 65.084403] systemd[1]: Started libcontainer container 886bab6837e970b4b9b5011e409a3738af2560e0059063c557f53be09ce14974. machine # [ 65.370359] dhcpcd[627]: veth62d1253d: soliciting a DHCP lease machine # [ 65.424450] dhcpcd[627]: veth4acc9f1a: using IPv4LL address 169.254.169.228 machine # [ 65.425513] dhcpcd[627]: veth4acc9f1a: adding route to 169.254.0.0/16 machine # [ 66.340108] dhcpcd[627]: veth62d1253d: soliciting an IPv6 router machine # [ 67.156237] systemd[1]: cri-containerd-886bab6837e970b4b9b5011e409a3738af2560e0059063c557f53be09ce14974.scope: Deactivated successfully. machine # [ 67.162125] systemd[1]: cri-containerd-886bab6837e970b4b9b5011e409a3738af2560e0059063c557f53be09ce14974.scope: Consumed 35ms CPU time over 2.070s wall clock time, 4.3M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic. machine # [ 67.257577] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-886bab6837e970b4b9b5011e409a3738af2560e0059063c557f53be09ce14974-rootfs.mount: Deactivated successfully. machine # [ 68.238933] dhcpcd[627]: veth4acc9f1a: no IPv6 Routers available machine # [ 69.287514] systemd[1]: cri-containerd-8a96748096812b7e95efca4f76161e02ae242758dd1e198d1d59ef381126c6f6.scope: Deactivated successfully. machine # [ 69.363176] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-8a96748096812b7e95efca4f76161e02ae242758dd1e198d1d59ef381126c6f6-rootfs.mount: Deactivated successfully. machine # [ 69.421806] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-8a96748096812b7e95efca4f76161e02ae242758dd1e198d1d59ef381126c6f6-shm.mount: Deactivated successfully. machine # [ 69.485278] cni0: port 2(veth62d1253d) entered disabled state machine # [ 69.488257] veth62d1253d (unregistering): left allmulticast mode machine # [ 69.488351] veth62d1253d (unregistering): left promiscuous mode machine # [ 69.488392] cni0: port 2(veth62d1253d) entered disabled state machine # [ 69.489165] dhcpcd[627]: veth62d1253d: carrier lost machine # [ 69.526657] systemd[1]: run-netns-cni\x2db8e093e1\x2d849e\x2d6ceb\x2dbd5e\x2d9fd7d2c96a55.mount: Deactivated successfully. machine # [ 69.552869] k3s[841]: I0916 20:19:20.434206 841 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/secret/c9b6cea6-b4a7-4f59-93ee-de241fc708c4-token\" (UniqueName: \"kubernetes.io/secret/c9b6cea6-b4a7-4f59-93ee-de241fc708c4-token\") pod \"c9b6cea6-b4a7-4f59-93ee-de241fc708c4\" (UID: \"c9b6cea6-b4a7-4f59-93ee-de241fc708c4\") " machine # [ 69.565182] systemd[1]: var-lib-kubelet-pods-c9b6cea6\x2db4a7\x2d4f59\x2d93ee\x2dde241fc708c4-volumes-kubernetes.io\x7esecret-token.mount: Deactivated successfully. machine # [ 69.567639] k3s[841]: I0916 20:19:20.447494 841 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/c9b6cea6-b4a7-4f59-93ee-de241fc708c4-token" pod "c9b6cea6-b4a7-4f59-93ee-de241fc708c4" (UID: "c9b6cea6-b4a7-4f59-93ee-de241fc708c4"). InnerVolumeSpecName "token". PluginName "kubernetes.io/secret", VolumeGIDValue "" machine # [ 69.579370] dhcpcd[627]: veth62d1253d: deleting address fe80::4cfa:c7ff:feed:9895 machine # [ 69.632314] dhcpcd[627]: veth62d1253d: removing interface machine # [ 69.652953] k3s[841]: I0916 20:19:20.534834 841 reconciler_common.go:299] "Volume detached for volume \"token\" (UniqueName: \"kubernetes.io/secret/c9b6cea6-b4a7-4f59-93ee-de241fc708c4-token\") on node \"machine\" DevicePath \"\"" machine # [ 69.984476] systemd[1]: Removed slice libcontainer container kubepods-besteffort-podc9b6cea6_b4a7_4f59_93ee_de241fc708c4.slice. machine # [ 69.989326] systemd[1]: kubepods-besteffort-podc9b6cea6_b4a7_4f59_93ee_de241fc708c4.slice: Consumed 60ms CPU time over 5.537s wall clock time, 4.8M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic. machine # [ 70.262336] k3s[841]: I0916 20:19:21.143953 841 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="8a96748096812b7e95efca4f76161e02ae242758dd1e198d1d59ef381126c6f6" machine: (finished: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s, in 5.96 seconds) (finished: subtest: gc cronjob runs against the service, in 6.17 seconds) subtest: helm test hook passes machine: must succeed: helm test -n niks3 niks3 --timeout 2m >&2 machine # [ 71.584988] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod7d4c8743_8a15_4c6c_8f6d_d9f7f398279f.slice. machine # [ 71.641213] cni0: port 2(veth7892121f) entered blocking state machine # [ 71.641276] cni0: port 2(veth7892121f) entered disabled state machine # [ 71.641316] veth7892121f: entered allmulticast mode machine # [ 71.641458] veth7892121f: entered promiscuous mode machine # [ 71.646897] (udev-worker)[2778]: Network interface NamePolicy= disabled on kernel command line. machine # [ 71.657272] cni0: port 2(veth7892121f) entered blocking state machine # [ 71.657330] cni0: port 2(veth7892121f) entered forwarding state machine # [ 71.699171] dhcpcd[627]: veth7892121f: IAID 2e:53:f6:96 machine # [ 71.700167] dhcpcd[627]: veth7892121f: adding address fe80::e058:2eff:fe53:f696 machine # [ 71.804428] systemd[1]: Started libcontainer container bb3a8c71481406aa984919aed77e58c78d981c051c7f80c7a217f4cd1c692841. machine # [ 71.932435] systemd[1]: Started libcontainer container ec4131e8809171093ee7e21af616023990e95a10559871039a37a67d9d52d720. machine # [ 71.985570] systemd[1]: cri-containerd-ec4131e8809171093ee7e21af616023990e95a10559871039a37a67d9d52d720.scope: Deactivated successfully. machine # [ 71.987694] systemd[1]: cri-containerd-ec4131e8809171093ee7e21af616023990e95a10559871039a37a67d9d52d720.scope: Consumed 26ms CPU time over 53ms wall clock time, 4.1M memory peak, 641B incoming IP traffic, 547B outgoing IP traffic. machine # [ 72.940215] dhcpcd[627]: veth7892121f: soliciting a DHCP lease machine # [ 73.316567] systemd[1]: cri-containerd-bb3a8c71481406aa984919aed77e58c78d981c051c7f80c7a217f4cd1c692841.scope: Deactivated successfully. machine # [ 73.383987] dhcpcd[627]: veth7892121f: soliciting an IPv6 router machine # [ 73.398493] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-bb3a8c71481406aa984919aed77e58c78d981c051c7f80c7a217f4cd1c692841-rootfs.mount: Deactivated successfully. machine # [ 73.458432] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-bb3a8c71481406aa984919aed77e58c78d981c051c7f80c7a217f4cd1c692841-shm.mount: Deactivated successfully. machine # [ 73.525998] cni0: port 2(veth7892121f) entered disabled state machine # [ 73.522102] dhcpcd[627]: veth7892121f: carrier lost machine # [ 73.530302] veth7892121f (unregistering): left allmulticast mode machine # [ 73.530375] veth7892121f (unregistering): left promiscuous mode machine # [ 73.530425] cni0: port 2(veth7892121f) entered disabled state machine # [ 73.572714] systemd[1]: run-netns-cni\x2db991d06c\x2de152\x2d3b8f\x2d8cb0\x2df59adf407860.mount: Deactivated successfully. machine # [ 73.584140] dhcpcd[627]: veth7892121f: deleting address fe80::e058:2eff:fe53:f696 machine # NAME: niks3 machine # LAST DEPLOYED: Wed Sep 16 20:19:04 2026 machine # NAMESPACE: niks3 machine # STATUS: deployed machine # REVISION: 1 machine # DESCRIPTION: Install complete machine # TEST SUITE: niks3-test machine # Last Started: Wed Sep 16 20:19:22 2026 machine # Last Completed: Wed Sep 16 20:19:24 2026 machine # Phase: Succeeded machine # [ 73.648527] dhcpcd[627]: veth7892121f: removing interface machine: (finished: must succeed: helm test -n niks3 niks3 --timeout 2m >&2, in 3.29 seconds) (finished: subtest: helm test hook passes, in 3.29 seconds) (finished: run the VM test script, in 74.78 seconds) test script finished in 74.82s cleanup kill QemuMachine (pid 45) machine # qemu-system-aarch64: terminating on signal 15 from pid 39 (/nix/store/3fl7bdkdxk2k4nssy1d1161isbzn6bsr-python3-3.14.7/bin/python3.14) machine # [2026-09-16T20:19:25Z INFO virtiofsd] Client disconnected, shutting down machine # [2026-09-16T20:19:25Z INFO virtiofsd] Client disconnected, shutting down machine # [2026-09-16T20:19:25Z INFO virtiofsd] Client disconnected, shutting down (finished: cleanup, in 0.84 seconds) additionally exposed symbols: machine, vlan1, 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_ssh time=2026-09-16T20:19:13.386Z level=INFO msg="Uploading 8 paths to localhost (0 already cached)" time=2026-09-16T20:19:13.386Z level=INFO msg="Uploading vl8mv2wi47vcylgmn3yzi4kyj5iqqchw-niks3-1.11.0 (7.1MB)" time=2026-09-16T20:19:13.386Z level=INFO msg="Uploading m54cs0m994hc3n9lax7sg98sgy729qsa-glibc-2.42-84 (44.4MB)" time=2026-09-16T20:19:13.388Z level=INFO msg="Uploading n7aaryickpnkwwmmkg7xgnlihmmsh55w-mailcap-2.1.54 (116.6KB)" time=2026-09-16T20:19:13.392Z level=INFO msg="Uploading 0s40b0an0cz4vypbji92cb7qbr65icl4-libidn2-2.3.8 (366.1KB)" time=2026-09-16T20:19:13.393Z level=INFO msg="Uploading i8an849ir6g3f4n2wrsm88s2qgrzjayq-tzdata-2026c (2.0MB)" time=2026-09-16T20:19:13.396Z level=INFO msg="Uploading na3qajp3ja0w9yxcsqck86phm9ddhwx2-iana-etc-20251215 (557.8KB)" time=2026-09-16T20:19:13.403Z level=INFO msg="Uploading waax852balprvsvdziyaf1h7r3ldvakg-xgcc-15.3.0-libgcc (150.1KB)" time=2026-09-16T20:19:13.405Z level=INFO msg="Uploading h0hd048jzxs7fx9a6g75jwrrhbg50bp8-libunistring-1.4.2 (2.0MB)" time=2026-09-16T20:19:14.838Z level=INFO msg="Uploading 8 narinfos" time=2026-09-16T20:19:14.880Z level=INFO msg="Upload complete. (1.783s)"