vm-test-run-nixos-test-k3s
checks.aarch64-linux.nixos-test-k3s
· build #185
· raw
1tribuchet: building on eliza2Machine state will be reset. To keep it, pass --keep-machine-state3start all VLans4(finished: start all VLans, in 0.00 seconds)5Test will time out and terminate in 3600.0 seconds6run the VM test script7machine: waiting for unit k3s.service8machine: waiting for the VM to finish booting9machine: starting vm10machine # Disk image does not exist, creating the virtualisation disk image...11machine: QEMU running (pid 45)12machine # Formatting '/build/vm-state-machine/tmp.rtda5E2afG', fmt=raw size=858993459213machine # mke2fs 1.47.4 (6-Mar-2025)14machine # Discarding device blocks: 0/2097152 done15machine # Creating filesystem with 2097152 4k blocks and 524288 inodes16machine # Filesystem UUID: 07df23d9-ffa5-4cf5-8621-4fb43ce52dcb17machine # Superblock backups stored on blocks:18machine # 32768, 98304, 163840, 229376, 294912, 819200, 884736, 160563219machine # 20machine # Allocating group tables: 0/64 done21machine # Writing inode tables: 0/64 done22machine # Creating journal (16384 blocks): done23machine # Writing superblocks and filesystem accounting information: 0/64 done24machine # 25machine # Virtualisation disk image created.26machine # [ 0.000000] Booting Linux on physical CPU 0x0000000000 [0xc00fac40]27machine # [ 0.000000] Linux version 6.18.49 (nixbld@localhost) (gcc (GCC) 15.3.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT Wed Sep 2 12:31:51 UTC 202628machine # [ 0.000000] KASLR enabled29machine # [ 0.000000] random: crng init done30machine # [ 0.000000] Machine model: linux,dummy-virt31machine # [ 0.000000] efi: UEFI not found.32machine # [ 0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT33machine # [ 0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000ffffffff]34machine # [ 0.000000] NODE_DATA(0) allocated [mem 0xffdec0c0-0xffdef83f]35machine # [ 0.000000] Zone ranges:36machine # [ 0.000000] DMA [mem 0x0000000040000000-0x00000000ffffffff]37machine # [ 0.000000] DMA32 empty38machine # [ 0.000000] Normal empty39machine # [ 0.000000] Device empty40machine # [ 0.000000] Movable zone start for each node41machine # [ 0.000000] Early memory node ranges42machine # [ 0.000000] node 0: [mem 0x0000000040000000-0x00000000ffffffff]43machine # [ 0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000ffffffff]44machine # [ 0.000000] cma: Reserved 32 MiB at 0x00000000fac0000045machine # [ 0.000000] psci: probing for conduit method from DT.46machine # [ 0.000000] psci: PSCIv1.3 detected in firmware.47machine # [ 0.000000] psci: Using standard PSCI v0.2 function IDs48machine # [ 0.000000] psci: Trusted OS migration not required49machine # [ 0.000000] psci: SMC Calling Convention v1.150machine # [ 0.000000] smccc: KVM: hypervisor services detected (0x00000000 0x00000000 0x00000000 0x00000003)51machine # [ 0.000000] percpu: Embedded 76 pages/cpu s186648 r8192 d116456 u31129652machine # [ 0.000000] Detected PIPT I-cache on CPU053machine # [ 0.000000] CPU features: detected: Address authentication (architected QARMA5 algorithm)54machine # [ 0.000000] CPU features: detected: GICv3 CPU interface55machine # [ 0.000000] CPU features: detected: Spectre-v456machine # [ 0.000000] CPU features: detected: Spectre-BHB57machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC03_CPU_3858machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC04_CPU_2359machine # [ 0.000000] alternatives: applying boot alternatives60machine # [ 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/8l3j0y92b9f5chghjjjxpj0d3rgfrh73-nixos-system-machine-test/init regInfo=/nix/store/7bqg3fj30swhdzhm8371yvwipg6bai4l-closure-info/registration console=ttyAMA0,115200n8 console=tty061machine # [ 0.000000] Unknown kernel command line parameters "regInfo=/nix/store/7bqg3fj30swhdzhm8371yvwipg6bai4l-closure-info/registration", will be passed to user space.62machine # [ 0.000000] printk: log buffer data + meta data: 131072 + 458752 = 589824 bytes63machine # [ 0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)64machine # [ 0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)65machine # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size adjusted to 3MB66machine # [ 0.000000] software IO TLB: area num 2.67machine # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size roundup to 4MB68machine # [ 0.000000] software IO TLB: mapped [mem 0x00000000fa200000-0x00000000fa600000] (4MB)69machine # [ 0.000000] Fallback order for Node 0: 070machine # [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 78643271machine # [ 0.000000] Policy zone: DMA72machine # [ 0.000000] mem auto-init: stack:all(zero), heap alloc:on, heap free:off73machine # [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=174machine # [ 0.000000] allocated 6291456 bytes of page_ext75machine # [ 0.000000] ftrace: allocating 74886 entries in 294 pages76machine # [ 0.000000] ftrace: allocated 294 pages with 4 groups77machine # [ 0.000000] rcu: Hierarchical RCU implementation.78machine # [ 0.000000] rcu: RCU event tracing is enabled.79machine # [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=2.80machine # [ 0.000000] Trampoline variant of Tasks RCU enabled.81machine # [ 0.000000] Rude variant of Tasks RCU enabled.82machine # [ 0.000000] Tracing variant of Tasks RCU enabled.83machine # [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.84machine # [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=285machine # [ 0.000000] RCU Tasks: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.86machine # [ 0.000000] RCU Tasks Rude: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.87machine # [ 0.000000] RCU Tasks Trace: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.88machine # [ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 089machine # [ 0.000000] GICv3: 256 SPIs implemented90machine # [ 0.000000] GICv3: 0 Extended SPIs implemented91machine # [ 0.000000] Root IRQ handler: gic_handle_irq92machine # [ 0.000000] GICv3: GICv3 features: 16 PPIs, DirectLPI93machine # [ 0.000000] GICv3: GICD_CTLR.DS=1, SCR_EL3.FIQ=094machine # [ 0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a000095machine # [ 0.000000] ITS [mem 0x08080000-0x0809ffff]96machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Devices @45100000 (indirect, esz 8, psz 64K, shr 1)97machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @45110000 (flat, esz 8, psz 64K, shr 1)98machine # [ 0.000000] GICv3: using LPI property table @0x000000004512000099machine # [ 0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000045130000100machine # [ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.101machine # [ 0.000000] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns102machine # [ 0.000000] arch_timer: cp15 timer running at 1000.00MHz (virt).103machine # [ 0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns104machine # [ 0.000000] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns105machine # [ 0.000030] arm-pv: using stolen time PV106machine # [ 0.000375] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)107machine # [ 0.000545] Console: colour dummy device 80x25108machine # [ 0.000553] printk: legacy console [tty0] enabled109machine # [ 0.000743] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000)110machine # [ 0.000750] pid_max: default: 32768 minimum: 301111machine # [ 0.000820] LSM: initializing lsm=capability,landlock,yama,bpf,ima112machine # [ 0.000966] landlock: Up and running.113machine # [ 0.000969] Yama: becoming mindful.114machine # [ 0.001400] LSM support for eBPF active115machine # [ 0.001585] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)116machine # [ 0.001641] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)117machine # [ 0.002826] cacheinfo: Unable to detect cache hierarchy for CPU 0118machine # [ 0.003552] rcu: Hierarchical SRCU implementation.119machine # [ 0.003556] rcu: Max phase no-delay instances is 1000.120machine # [ 0.003745] Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level121machine # [ 0.004825] fsl-mc MSI: its@8080000 domain created122machine # [ 0.004917] EFI services will not be available.123machine # [ 0.005055] smp: Bringing up secondary CPUs ...124machine # [ 0.005745] Detected PIPT I-cache on CPU1125machine # [ 0.005857] GICv3: CPU1: found redistributor 1 region 0:0x00000000080c0000126machine # [ 0.005992] GICv3: CPU1: using allocated LPI pending table @0x0000000045140000127machine # [ 0.006126] CPU1: Booted secondary processor 0x0000000001 [0xc00fac40]128machine # [ 0.006709] smp: Brought up 1 node, 2 CPUs129machine # [ 0.006722] SMP: Total of 2 processors activated.130machine # [ 0.006725] CPU: All CPU(s) started at EL1131machine # [ 0.006734] CPU features: detected: Branch Target Identification132machine # [ 0.006738] CPU features: detected: ARMv8.4 Translation Table Level133machine # [ 0.006741] CPU features: detected: Instruction cache invalidation not required for I/D coherence134machine # [ 0.006744] CPU features: detected: Data cache clean to the PoU not required for I/D coherence135machine # [ 0.006748] CPU features: detected: Common not Private translations136machine # [ 0.006750] CPU features: detected: CRC32 instructions137machine # [ 0.006753] CPU features: detected: Data cache clean to Point of Deep Persistence138machine # [ 0.006756] CPU features: detected: Data cache clean to Point of Persistence139machine # [ 0.006759] CPU features: detected: Data independent timing control (DIT)140machine # [ 0.006762] CPU features: detected: E0PD141machine # [ 0.006764] CPU features: detected: Enhanced Counter Virtualization142machine # [ 0.006767] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF)143machine # [ 0.006771] CPU features: detected: Enhanced Virtualization Traps144machine # [ 0.006773] CPU features: detected: Fine Grained Traps145machine # [ 0.006776] CPU features: detected: Generic authentication (architected QARMA5 algorithm)146machine # [ 0.006781] CPU features: detected: RCpc load-acquire (LDAPR)147machine # [ 0.006783] CPU features: detected: LSE atomic instructions148machine # [ 0.006786] CPU features: detected: Privileged Access Never149machine # [ 0.006789] CPU features: detected: PMUv3150machine # [ 0.006791] CPU features: detected: RAS Extension Support151machine # [ 0.006794] CPU features: detected: RASv1p1 Extension Support152machine # [ 0.006797] CPU features: detected: Random Number Generator153machine # [ 0.006799] CPU features: detected: Speculation barrier (SB)154machine # [ 0.006802] CPU features: detected: Stage-2 Force Write-Back155machine # [ 0.006805] CPU features: detected: TLB range maintenance instructions156machine # [ 0.006809] CPU features: detected: Speculative Store Bypassing Safe (SSBS)157machine # [ 0.006923] alternatives: applying system-wide alternatives158machine # [ 0.009872] CPU features: detected: BBM Level 2 without TLB conflict abort159machine # [ 0.010104] Memory: 2945348K/3145728K available (24448K kernel code, 7090K rwdata, 26344K rodata, 4736K init, 1107K bss, 153744K reserved, 32768K cma-reserved)160machine # [ 0.011646] devtmpfs: initialized161machine # [ 0.014244] posixtimers hash table entries: 1024 (order: 2, 16384 bytes, linear)162machine # [ 0.014282] futex hash table entries: 512 (32768 bytes on 1 NUMA nodes, total 32 KiB, linear).163machine # [ 0.014469] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL164machine # [ 0.014475] 0 pages in range for non-PLT usage165machine # [ 0.014476] 508288 pages in range for PLT usage166machine # [ 0.014611] pinctrl core: initialized pinctrl subsystem167machine # [ 0.015410] DMI not present or invalid.168machine # [ 0.018664] NET: Registered PF_NETLINK/PF_ROUTE protocol family169machine # [ 0.021036] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations170machine # [ 0.021329] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations171machine # [ 0.021661] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations172machine # [ 0.021682] audit: initializing netlink subsys (disabled)173machine # [ 0.022545] audit: type=2000 audit(0.020:1): state=initialized audit_enabled=0 res=1174machine # [ 0.025173] thermal_sys: Registered thermal governor 'fair_share'175machine # [ 0.025182] thermal_sys: Registered thermal governor 'bang_bang'176machine # [ 0.025197] thermal_sys: Registered thermal governor 'step_wise'177machine # [ 0.025204] thermal_sys: Registered thermal governor 'user_space'178machine # [ 0.025212] thermal_sys: Registered thermal governor 'power_allocator'179machine # [ 0.025339] cpuidle: using governor ladder180machine # [ 0.025398] cpuidle: using governor menu181machine # [ 0.026302] hw-breakpoint: found 16 breakpoint and 4 watchpoint registers.182machine # [ 0.026374] ASID allocator initialised with 65536 entries183machine # [ 0.030374] Serial: AMBA PL011 UART driver184machine # [ 0.047062] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 13, base_baud = 0) is a PL011 rev1185machine # [ 0.047538] printk: console [ttyAMA0] enabled186machine # [ 0.075340] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages187machine # [ 0.075356] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page188machine # [ 0.075360] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages189machine # [ 0.075364] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page190machine # [ 0.075367] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages191machine # [ 0.075370] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page192machine # [ 0.075374] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages193machine # [ 0.075377] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page194machine # [ 0.087285] fbcon: Taking over console195machine # [ 0.087305] ACPI: Interpreter disabled.196machine # [ 0.088911] iommu: Default domain type: Translated197machine # [ 0.088916] iommu: DMA domain TLB invalidation policy: strict mode198machine # [ 0.090844] SCSI subsystem initialized199machine # [ 0.094852] usbcore: registered new interface driver usbfs200machine # [ 0.094891] usbcore: registered new interface driver hub201machine # [ 0.094921] usbcore: registered new device driver usb202machine # [ 0.095448] pps_core: LinuxPPS API ver. 1 registered203machine # [ 0.095453] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>204machine # [ 0.095468] PTP clock support registered205machine # [ 0.095534] EDAC MC: Ver: 3.0.0206machine # [ 0.095835] scmi_core: SCMI protocol bus registered207machine # [ 0.096588] FPGA manager framework208machine # [ 0.097530] vgaarb: loaded209machine # [ 0.098807] clocksource: Switched to clocksource arch_sys_counter210machine # [ 0.099807] VFS: Disk quotas dquot_6.6.0211machine # [ 0.099851] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)212machine # [ 0.106552] netfs: FS-Cache loaded213machine # [ 0.106735] pnp: PnP ACPI: disabled214machine # [ 0.110901] NET: Registered PF_INET protocol family215machine # [ 0.111525] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)216machine # [ 0.145458] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)217machine # [ 0.145518] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)218machine # [ 0.145561] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)219machine # [ 0.145755] TCP bind hash table entries: 32768 (order: 8, 1048576 bytes, linear)220machine # [ 0.146056] TCP: Hash tables configured (established 32768 bind 32768)221machine # [ 0.146197] MPTCP token hash table entries: 4096 (order: 5, 98304 bytes, linear)222machine # [ 0.146249] UDP hash table entries: 2048 (order: 5, 131072 bytes, linear)223machine # [ 0.146316] UDP-Lite hash table entries: 2048 (order: 5, 131072 bytes, linear)224machine # [ 0.146457] NET: Registered PF_UNIX/PF_LOCAL protocol family225machine # [ 0.146513] NET: Registered PF_XDP protocol family226machine # [ 0.146532] PCI: CLS 0 bytes, default 64227machine # [ 0.146951] Trying to unpack rootfs image as initramfs...228machine # [ 0.155037] kvm [1]: HYP mode not available229machine # [ 0.276841] Initialise system trusted keyrings230machine # [ 0.277030] workingset: timestamp_bits=42 max_order=20 bucket_order=0231machine # [ 0.277478] squashfs: version 4.0 (2009/01/31) Phillip Lougher232machine # [ 0.277545] 9p: Installing v9fs 9p2000 file system support233machine # [ 0.289535] Key type asymmetric registered234machine # [ 0.289548] Asymmetric key parser 'x509' registered235machine # [ 0.289606] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 242)236machine # [ 0.289702] io scheduler mq-deadline registered237machine # [ 0.289711] io scheduler kyber registered238machine # [ 0.299209] pl061_gpio 9030000.pl061: PL061 GPIO chip registered239machine # [ 0.302857] ledtrig-cpu: registered to indicate activity on CPUs240machine # [ 0.303351] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:241machine # [ 0.303374] pci-host-generic 4010000000.pcie: IO 0x003eff0000..0x003effffff -> 0x0000000000242machine # [ 0.303393] pci-host-generic 4010000000.pcie: MEM 0x0010000000..0x003efeffff -> 0x0010000000243machine # [ 0.303404] pci-host-generic 4010000000.pcie: MEM 0x8000000000..0xffffffffff -> 0x8000000000244machine # [ 0.303433] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits245machine # [ 0.303464] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]246machine # [ 0.303570] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00247machine # [ 0.303582] pci_bus 0000:00: root bus resource [bus 00-ff]248machine # [ 0.303591] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]249machine # [ 0.303599] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]250machine # [ 0.303606] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]251machine # [ 0.303671] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint252machine # [ 0.304148] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint253machine # [ 0.304352] pci 0000:00:01.0: BAR 0 [io 0x0000-0x001f]254machine # [ 0.304371] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff]255machine # [ 0.304407] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]256machine # [ 0.304425] pci 0000:00:01.0: ROM [mem 0x00000000-0x0003ffff pref]257machine # [ 0.304882] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint258machine # [ 0.305086] pci 0000:00:02.0: BAR 0 [io 0x0000-0x001f]259machine # [ 0.305104] pci 0000:00:02.0: BAR 1 [mem 0x00000000-0x00000fff]260machine # [ 0.305138] pci 0000:00:02.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]261machine # [ 0.305623] pci 0000:00:03.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint262machine # [ 0.305808] pci 0000:00:03.0: BAR 0 [io 0x0000-0x003f]263machine # [ 0.305830] pci 0000:00:03.0: BAR 1 [mem 0x00000000-0x00000fff]264machine # [ 0.305865] pci 0000:00:03.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]265machine # [ 0.306353] pci 0000:00:04.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint266machine # [ 0.306542] pci 0000:00:04.0: BAR 0 [io 0x0000-0x001f]267machine # [ 0.306561] pci 0000:00:04.0: BAR 1 [mem 0x00000000-0x00000fff]268machine # [ 0.306593] pci 0000:00:04.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]269machine # [ 0.336408] pci 0000:00:05.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint270machine # [ 0.336623] pci 0000:00:05.0: BAR 0 [io 0x0000-0x001f]271machine # [ 0.336643] pci 0000:00:05.0: BAR 1 [mem 0x00000000-0x00000fff]272machine # [ 0.336677] pci 0000:00:05.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]273machine # [ 0.337190] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint274machine # [ 0.337383] pci 0000:00:06.0: BAR 0 [io 0x0000-0x007f]275machine # [ 0.337403] pci 0000:00:06.0: BAR 1 [mem 0x00000000-0x00000fff]276machine # [ 0.337436] pci 0000:00:06.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]277machine # [ 0.337931] pci 0000:00:07.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint278machine # [ 0.338122] pci 0000:00:07.0: BAR 0 [io 0x0000-0x001f]279machine # [ 0.338142] pci 0000:00:07.0: BAR 1 [mem 0x00000000-0x00000fff]280machine # [ 0.338186] pci 0000:00:07.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]281machine # [ 0.338206] pci 0000:00:07.0: ROM [mem 0x00000000-0x0003ffff pref]282machine # [ 0.338725] pci 0000:00:08.0: [1af4:1050] type 00 class 0x038000 conventional PCI endpoint283machine # [ 0.351369] pci 0000:00:08.0: BAR 1 [mem 0x00000000-0x00000fff]284machine # [ 0.351405] pci 0000:00:08.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]285machine # [ 0.351876] pci 0000:00:09.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint286machine # [ 0.352067] pci 0000:00:09.0: BAR 1 [mem 0x00000000-0x00000fff]287machine # [ 0.352096] pci 0000:00:09.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]288machine # [ 0.352497] pci 0000:00:0a.0: [8086:24cd] type 00 class 0x0c0320 conventional PCI endpoint289machine # [ 0.352684] pci 0000:00:0a.0: BAR 0 [mem 0x00000000-0x00000fff]290machine # [ 0.352941] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint291machine # [ 0.353227] pci 0000:00:0b.0: BAR 0 [io 0x0000-0x003f]292machine # [ 0.353248] pci 0000:00:0b.0: BAR 1 [mem 0x00000000-0x00000fff]293machine # [ 0.353282] pci 0000:00:0b.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]294machine # [ 0.353771] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint295machine # [ 0.353960] pci 0000:00:0c.0: BAR 0 [io 0x0000-0x001f]296machine # [ 0.353979] pci 0000:00:0c.0: BAR 1 [mem 0x00000000-0x00000fff]297machine # [ 0.354012] pci 0000:00:0c.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]298machine # [ 0.354692] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned299machine # [ 0.354708] pci 0000:00:07.0: ROM [mem 0x10040000-0x1007ffff pref]: assigned300machine # [ 0.354715] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned301machine # [ 0.354761] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned302machine # [ 0.371348] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned303machine # [ 0.371399] pci 0000:00:04.0: BAR 4 [mem 0x800000c000-0x800000ffff 64bit pref]: assigned304machine # [ 0.371445] pci 0000:00:05.0: BAR 4 [mem 0x8000010000-0x8000013fff 64bit pref]: assigned305machine # [ 0.371492] pci 0000:00:06.0: BAR 4 [mem 0x8000014000-0x8000017fff 64bit pref]: assigned306machine # [ 0.371538] pci 0000:00:07.0: BAR 4 [mem 0x8000018000-0x800001bfff 64bit pref]: assigned307machine # [ 0.371587] pci 0000:00:08.0: BAR 4 [mem 0x800001c000-0x800001ffff 64bit pref]: assigned308machine # [ 0.371634] pci 0000:00:09.0: BAR 4 [mem 0x8000020000-0x8000023fff 64bit pref]: assigned309machine # [ 0.371682] pci 0000:00:0b.0: BAR 4 [mem 0x8000024000-0x8000027fff 64bit pref]: assigned310machine # [ 0.371770] pci 0000:00:0c.0: BAR 4 [mem 0x8000028000-0x800002bfff 64bit pref]: assigned311machine # [ 0.371817] pci 0000:00:01.0: BAR 1 [mem 0x10080000-0x10080fff]: assigned312machine # [ 0.371839] pci 0000:00:02.0: BAR 1 [mem 0x10081000-0x10081fff]: assigned313machine # [ 0.371860] pci 0000:00:03.0: BAR 1 [mem 0x10082000-0x10082fff]: assigned314machine # [ 0.371883] pci 0000:00:04.0: BAR 1 [mem 0x10083000-0x10083fff]: assigned315machine # [ 0.371905] pci 0000:00:05.0: BAR 1 [mem 0x10084000-0x10084fff]: assigned316machine # [ 0.371927] pci 0000:00:06.0: BAR 1 [mem 0x10085000-0x10085fff]: assigned317machine # [ 0.371949] pci 0000:00:07.0: BAR 1 [mem 0x10086000-0x10086fff]: assigned318machine # [ 0.371971] pci 0000:00:08.0: BAR 1 [mem 0x10087000-0x10087fff]: assigned319machine # [ 0.371993] pci 0000:00:09.0: BAR 1 [mem 0x10088000-0x10088fff]: assigned320machine # [ 0.372016] pci 0000:00:0a.0: BAR 0 [mem 0x10089000-0x10089fff]: assigned321machine # [ 0.372039] pci 0000:00:0b.0: BAR 1 [mem 0x1008a000-0x1008afff]: assigned322machine # [ 0.372061] pci 0000:00:0c.0: BAR 1 [mem 0x1008b000-0x1008bfff]: assigned323machine # [ 0.372083] pci 0000:00:06.0: BAR 0 [io 0x1000-0x107f]: assigned324machine # [ 0.372105] pci 0000:00:03.0: BAR 0 [io 0x1080-0x10bf]: assigned325machine # [ 0.372126] pci 0000:00:0b.0: BAR 0 [io 0x10c0-0x10ff]: assigned326machine # [ 0.372148] pci 0000:00:01.0: BAR 0 [io 0x1100-0x111f]: assigned327machine # [ 0.372169] pci 0000:00:02.0: BAR 0 [io 0x1120-0x113f]: assigned328machine # [ 0.372191] pci 0000:00:04.0: BAR 0 [io 0x1140-0x115f]: assigned329machine # [ 0.372213] pci 0000:00:05.0: BAR 0 [io 0x1160-0x117f]: assigned330machine # [ 0.372235] pci 0000:00:07.0: BAR 0 [io 0x1180-0x119f]: assigned331machine # [ 0.372258] pci 0000:00:0c.0: BAR 0 [io 0x11a0-0x11bf]: assigned332machine # [ 0.372284] pci_bus 0000:00: resource 4 [io 0x0000-0xffff]333machine # [ 0.372294] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]334machine # [ 0.372299] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]335machine # [ 0.373507] pci 0000:00:0a.0: enabling device (0000 -> 0002)336machine # [ 0.423005] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)337machine # [ 0.425377] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)338machine # [ 0.427796] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)339machine # [ 0.430249] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)340machine # [ 0.437987] virtio-pci 0000:00:05.0: enabling device (0000 -> 0003)341machine # [ 0.441245] virtio-pci 0000:00:06.0: enabling device (0000 -> 0003)342machine # [ 0.444581] virtio-pci 0000:00:07.0: enabling device (0000 -> 0003)343machine # [ 0.447877] virtio-pci 0000:00:08.0: enabling device (0000 -> 0002)344machine # [ 0.454645] virtio-pci 0000:00:09.0: enabling device (0000 -> 0002)345machine # [ 0.457753] virtio-pci 0000:00:0b.0: enabling device (0000 -> 0003)346machine # [ 0.461170] virtio-pci 0000:00:0c.0: enabling device (0000 -> 0003)347machine # [ 0.468464] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled348machine # [ 0.471860] msm_serial: driver initialized349machine # [ 0.472069] SuperH (H)SCI(F) driver initialized350machine # [ 0.472136] STM32 USART driver initialized351machine # [ 0.495854] loop: module loaded352machine # [ 0.496098] virtio_blk virtio5: 2/0/0 default/read/poll queues353machine # [ 0.497358] virtio_blk virtio5: [vda] 16777216 512-byte logical blocks (8.59 GB/8.00 GiB)354machine # [ 0.502515] megasas: 07.734.00.00-rc1355machine # [ 0.504009] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]356machine # [ 0.513126] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000357machine # [ 0.513191] Intel/Sharp Extended Query Table at 0x0031358machine # [ 0.517781] Using buffer write method359machine # [ 0.517861] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]360machine # [ 0.521249] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000361machine # [ 0.521342] Intel/Sharp Extended Query Table at 0x0031362machine # [ 0.526131] Using buffer write method363machine # [ 0.526189] Concatenating MTD devices:364machine # [ 0.526194] (0): "0.flash"365machine # [ 0.526199] (1): "0.flash"366machine # [ 0.526204] into device "0.flash"367machine # [ 0.621559] Freeing initrd memory: 26088K368machine # [ 0.629201] tun: Universal TUN/TAP device driver, 1.6369machine # [ 0.633582] thunder_xcv, ver 1.0370machine # [ 0.633637] thunder_bgx, ver 1.0371machine # [ 0.633659] nicpf, ver 1.0372machine # [ 0.634280] e1000: Intel(R) PRO/1000 Network Driver373machine # [ 0.634284] e1000: Copyright (c) 1999-2006 Intel Corporation.374machine # [ 0.634310] e1000e: Intel(R) PRO/1000 Network Driver375machine # [ 0.634316] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.376machine # [ 0.634338] igb: Intel(R) Gigabit Ethernet Network Driver377machine # [ 0.634341] igb: Copyright (c) 2007-2014 Intel Corporation.378machine # [ 0.634360] igbvf: Intel(R) Gigabit Virtual Function Network Driver379machine # [ 0.634364] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.380machine # [ 0.634507] sky2: driver version 1.30381machine # [ 0.636301] usbcore: registered new interface driver usb-storage382machine # [ 0.636418] usbcore: registered new interface driver usbserial_generic383machine # [ 0.636430] usbserial: USB Serial support registered for generic384machine # [ 0.637090] hv_vmbus: registering driver hyperv_keyboard385machine # [ 0.638179] rtc-pl031 9010000.pl031: registered as rtc0386machine # [ 0.638209] rtc-pl031 9010000.pl031: setting system clock to 2026-09-08T08:16:45 UTC (1788855405)387machine # [ 0.638557] i2c_dev: i2c /dev entries driver388machine # [ 0.640718] ehci-pci 0000:00:0a.0: EHCI Host Controller389machine # [ 0.640790] ehci-pci 0000:00:0a.0: new USB bus registered, assigned bus number 1390machine # [ 0.641432] ehci-pci 0000:00:0a.0: irq 15, io mem 0x10089000391machine # [ 0.641448] sdhci: Secure Digital Host Controller Interface driver392machine # [ 0.641456] sdhci: Copyright(c) Pierre Ossman393machine # [ 0.641727] Synopsys Designware Multimedia Card Interface Driver394machine # [ 0.642104] sdhci-pltfm: SDHCI platform and OF driver helper395machine # [ 0.644081] hid: raw HID events driver (C) Jiri Kosina396machine # [ 0.644414] usbcore: registered new interface driver usbhid397machine # [ 0.644418] usbhid: USB HID core driver398machine # [ 0.648287] hw perfevents: enabled with armv8_pmuv3 PMU driver, 11 (0,800003ff) counters available399machine # [ 0.649948] drop_monitor: Initializing network drop monitor service400machine # [ 0.650086] NET: Registered PF_INET6 protocol family401machine # [ 0.650915] Segment Routing with IPv6402machine # [ 0.650931] In-situ OAM (IOAM) with IPv6403machine # [ 0.650992] NET: Registered PF_PACKET protocol family404machine # [ 0.651090] 9pnet: Installing 9P2000 support405machine # [ 0.653484] Key type dns_resolver registered406machine # [ 0.660497] registered taskstats version 1407machine # [ 0.660669] Loading compiled-in X.509 certificates408machine # [ 0.669058] ehci-pci 0000:00:0a.0: USB 2.0 started, EHCI 1.00409machine # [ 0.669529] hub 1-0:1.0: USB hub found410machine # [ 0.669589] hub 1-0:1.0: 6 ports detected411machine # [ 0.673080] Demotion targets for Node 0: null412machine # [ 0.673279] Key type .fscrypt registered413machine # [ 0.673283] Key type fscrypt-provisioning registered414machine # [ 0.673411] ima: No TPM chip found, activating TPM-bypass!415machine # [ 0.673430] ima: Allocated hash algorithm: sha1416machine # [ 0.673452] ima: No architecture policies found417machine # [ 0.674310] input: gpio-keys as /devices/platform/gpio-keys/input/input0418machine # [ 0.692917] clk: Disabling unused clocks419machine # [ 0.692937] PM: genpd: Disabling unused power domains420machine # [ 0.700568] Freeing unused kernel memory: 4736K421machine # [ 0.700788] Run /init as init process422machine # [ 0.736804] systemd[1]: Successfully made /usr/ read-only.423machine # [ 0.918970] usb 1-1: new high-speed USB device number 2 using ehci-pci424machine # [ 1.071529] input: QEMU QEMU USB Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:0a.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input1425machine # [ 1.072334] 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)426machine # [ 1.072380] systemd[1]: Detected virtualization qemu.427machine # [ 1.072466] systemd[1]: Detected architecture arm64.428machine # [ 1.072482] systemd[1]: Running in initrd.429machine # [ 1.073595] systemd[1]: Initializing machine ID from random generator.430machine # [ 1.073989] systemd[1]: Hostname set to <machine>.431machine # [ 1.159289] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:0a.0-1/input0432machine # [ 1.278887] usb 1-2: new high-speed USB device number 3 using ehci-pci433machine # [ 1.308017] systemd[1]: bpf-restrict-fs: LSM BPF program attached434machine # [ 1.412237] systemd[1]: Queued start job for default target Initrd Default Target.435machine # [ 1.431698] systemd[1]: Created slice Slice /system/modprobe.436machine # [ 1.432060] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.437machine # [ 1.432106] systemd[1]: Expecting device /dev/disk/by-label/nixos...438machine # [ 1.432142] systemd[1]: Reached target Path Units.439machine # [ 1.432164] systemd[1]: Reached target Slice Units.440machine # [ 1.432189] systemd[1]: Reached target Swaps.441machine # [ 1.432214] systemd[1]: Reached target Timer Units.442machine # [ 1.432475] systemd[1]: Listening on D-Bus System Message Bus Socket.443machine # [ 1.432716] systemd[1]: Listening on Journal Socket (/dev/log).444machine # [ 1.432938] systemd[1]: Listening on Journal Sockets.445machine # [ 1.433150] systemd[1]: Listening on udev Control Socket.446machine # [ 1.433278] systemd[1]: Listening on udev Kernel Socket.447machine # [ 1.433305] systemd[1]: Reached target Socket Units.448machine # [ 1.435870] systemd[1]: Starting Create List of Static Device Nodes...449machine # [ 1.451151] systemd[1]: Starting Load Kernel Module 9pnet_virtio...450machine # [ 1.451305] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs451machine # [ 1.459022] systemd[1]: Mounting Kernel Configuration File System...452machine # [ 1.476685] input: QEMU QEMU USB Tablet as /devices/platform/4010000000.pcie/pci0000:00/0000:00:0a.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input2453machine # [ 1.482480] hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:0a.0-2/input0454machine # [ 1.488727] systemd[1]: Starting Journal Service...455machine # [ 1.499183] systemd[1]: Starting Load Kernel Modules...456machine # [ 1.499328] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os457machine # [ 1.500869] systemd[1]: Starting Coldplug All udev Devices...458machine # [ 1.502591] systemd[1]: Finished Create List of Static Device Nodes.459machine # [ 1.511681] systemd[1]: Mounted Kernel Configuration File System.460machine # [ 1.521613] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...461machine # [ 1.535586] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.462machine # [ 1.536020] systemd[1]: Finished Load Kernel Module 9pnet_virtio.463machine # [ 1.549805] systemd-journald[81]: Collecting audit messages is disabled.464machine # [ 1.558783] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.465machine # [ 1.561122] [drm] pci: virtio-gpu-pci detected at 0000:00:08.0466machine # [ 1.561436] [drm] features: -virgl +edid -resource_blob -host_visible467machine # [ 1.561458] [drm] features: -context_init468machine # [ 1.564871] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev469machine # [ 1.567768] [drm] number of scanouts: 1470machine # [ 1.567814] [drm] number of cap sets: 0471machine # [ 1.579073] virtio-pci 0000:00:08.0: [drm] Registered 1 planes with drm panic472machine # [ 1.579101] [drm] Initialized virtio_gpu 0.1.0 for 0000:00:08.0 on minor 0473machine # [ 1.591034] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.474machine # [ 1.594919] systemd[1]: Starting Create Static Device Nodes in /dev...475machine # [ 1.618860] Console: switching to colour frame buffer device 160x50476machine # [ 1.619601] virtio-pci 0000:00:08.0: [drm] fb0: virtio_gpudrmfb frame buffer device477machine # [ 1.650784] systemd[1]: Finished Load Kernel Modules.478machine # [ 1.651155] systemd[1]: Started Journal Service.479machine # [ 1.649776] systemd-modules-load[82]: Using 2 probe threads480machine # [ 1.657762] systemd-modules-load[82]: Module 'virtio_balloon' is built in481machine # [ 1.659151] systemd-modules-load[82]: Module 'virtio_console' is built in482machine # [ 1.660542] systemd-modules-load[82]: Inserted module 'dm_mod'483machine # [ 1.661707] systemd-modules-load[82]: Module 'virtio_rng' is built in484machine # [ 1.663933] systemd-modules-load[82]: Inserted module 'virtio_gpu'485machine # [ 1.665581] systemd[1]: Starting Apply Kernel Variables...486machine # [ 1.666720] systemd[1]: Finished Create Static Device Nodes in /dev.487machine # [ 1.670813] systemd[1]: Reached target Preparation for Local File Systems.488machine # [ 1.672777] systemd[1]: Reached target Local File Systems.489machine # [ 1.688404] systemd[1]: Starting Create System Files and Directories...490machine # [ 1.693064] systemd[1]: Starting Rule-based Manager for Device Events and Files...491machine # [ 1.695671] systemd[1]: Finished Apply Kernel Variables.492machine # [ 1.734592] systemd[1]: Finished Create System Files and Directories.493machine # [ 1.747783] systemd-udevd[97]: Using default interface naming scheme 'v261'.494machine # [ 1.764505] systemd[1]: Started Rule-based Manager for Device Events and Files.495machine # [ 1.806274] systemd[1]: Starting Virtual Console Setup...496machine # [ 1.850892] systemd-vconsole-setup[114]: Configuration of first virtual console was skipped, ignoring remaining ones.497machine # [ 1.855101] systemd[1]: Finished Virtual Console Setup.498machine # [ 2.277771] systemd[1]: Finished Coldplug All udev Devices.499machine # [ 2.280000] systemd[1]: Reached target System Initialization.500machine # [ 2.281529] systemd[1]: Reached target Basic System.501machine # [ 2.472396] (udev-worker)[103]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.502machine # [ 2.480214] (udev-worker)[103]: Network interface NamePolicy= disabled on kernel command line.503machine # [ 2.483752] (udev-worker)[109]: Network interface NamePolicy= disabled on kernel command line.504machine # [ 2.513904] systemd[1]: Found device /dev/disk/by-label/nixos.505machine # [ 2.515964] systemd[1]: Reached target Initrd Root Device.506machine # [ 2.519635] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos...507machine # [ 2.576245] systemd-fsck[132]: nixos: clean, 12/524288 files, 58513/2097152 blocks508machine # [ 2.585831] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos.509machine # [ 2.588114] systemd[1]: Mounting /sysroot...510machine # [ 2.678312] EXT4-fs (vda): mounted filesystem 07df23d9-ffa5-4cf5-8621-4fb43ce52dcb r/w with ordered data mode. Quota mode: none.511machine # [ 2.681919] systemd[1]: Mounted /sysroot.512machine # [ 2.683367] systemd[1]: Reached target Initrd Root File System.513machine # [ 2.688473] systemd[1]: Starting Mountpoints Configured in the Real Root...514machine # [ 2.723672] systemd-sysroot-fstab-check[140]: /sysroot should be mounted in the initrd, will request daemon-reload.515machine # [ 2.731282] systemd[1]: Reload requested from client PID 140 ('systemd-sysroot') (unit initrd-parse-etc.service)...516machine # [ 2.733444] systemd[1]: Reloading...517machine # [ 2.872900] systemd[1]: Reloading finished in 143 ms.518machine # [ 2.915731] systemd-sysroot-fstab-check[140]: Requesting initrd-fs.target/start/replace...519machine # [ 2.919918] systemd-sysroot-fstab-check[140]: Requesting swap.target/start/replace...520machine # [ 2.925715] systemd[1]: Starting Load Kernel Module 9pnet_virtio...521machine # [ 2.927861] systemd[1]: initrd-parse-etc.service: Deactivated successfully.522machine # [ 2.932934] systemd[1]: Finished Mountpoints Configured in the Real Root.523machine # [ 2.936105] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies.524machine # [ 2.958556] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.525machine # [ 2.959943] systemd[1]: Finished Load Kernel Module 9pnet_virtio.526machine # [ 3.372949] (udev-worker)[109]: mtd0ro: Failed to find and pin callout binary "/nix/store/awq6qdiyxlvdp21km39qj020fcshgkia-systemd-261.2/lib/udev/mtd_probe": No such file or directory527machine # [ 3.380294] (udev-worker)[109]: mtd0ro: /nix/store/awq6qdiyxlvdp21km39qj020fcshgkia-systemd-261.2/lib/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 directory528machine # [ 3.390023] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.529machine # [ 3.391406] systemd[1]: Stopped Virtual Console Setup.530machine # [ 3.392478] systemd[1]: Stopping Virtual Console Setup...531machine # [ 3.393448] systemd[1]: Starting Virtual Console Setup...532machine # [ 3.431898] systemd-vconsole-setup[162]: Configuration of first virtual console was skipped, ignoring remaining ones.533machine # [ 3.435127] systemd[1]: Finished Virtual Console Setup.534machine # [ 3.507279] systemd[1]: Mounting /sysroot/nix/.ro-store...535machine # [ 3.510796] systemd[1]: Mounting /sysroot/nix/.rw-store...536machine # [ 3.528878] systemd[1]: Mounting /sysroot/run...537machine # [ 3.540637] systemd[1]: Mounting /sysroot/tmp/shared...538machine # [ 3.561519] systemd[1]: Mounting /sysroot/tmp/xchg...539machine # [ 3.570179] systemd[1]: Mounted /sysroot/nix/.ro-store.540machine # [ 3.575952] systemd[1]: Mounted /sysroot/nix/.rw-store.541machine # [ 3.577391] systemd[1]: Mounted /sysroot/run.542machine # [ 3.584900] systemd[1]: Mounted /sysroot/tmp/shared.543machine # [ 3.592758] systemd[1]: Starting rw-sysroot-nix-store.service...544machine # [ 3.594278] systemd[1]: Mounted /sysroot/tmp/xchg.545machine # [ 3.608966] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.546machine # [ 3.612310] systemd[1]: Finished rw-sysroot-nix-store.service.547machine # [ 3.614801] systemd[1]: Mounting /sysroot/nix/store...548machine # [ 3.669119] systemd[1]: Mounted /sysroot/nix/store.549machine # [ 3.670773] systemd[1]: Reached target Initrd File Systems.550machine # [ 3.680179] systemd[1]: Starting Find NixOS closure...551machine # [ 3.682079] systemd[1]: Starting Create Volatile Files and Directories in the Real Root...552machine # [ 3.716187] systemd[1]: Finished Create Volatile Files and Directories in the Real Root.553machine # [ 3.729210] systemd[1]: Finished Find NixOS closure.554machine # [ 3.730657] systemd[1]: Reached target Initrd Default Target.555machine # [ 3.732957] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...556machine # [ 3.765471] systemd[1]: Stopped target Initrd Default Target.557machine # [ 3.767159] systemd[1]: Stopped target Basic System.558machine # [ 3.768700] systemd[1]: Stopped target Initrd Root Device.559machine # [ 3.770129] systemd[1]: Stopped target Path Units.560machine # [ 3.771390] systemd[1]: systemd-ask-password-console.path: Deactivated successfully.561machine # [ 3.773425] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.562machine # [ 3.775378] systemd[1]: Stopped target Slice Units.563machine # [ 3.776660] systemd[1]: Stopped target Socket Units.564machine # [ 3.777903] systemd[1]: Stopped target System Initialization.565machine # [ 3.779299] systemd[1]: Stopped target Swaps.566machine # [ 3.780445] systemd[1]: Stopped target Timer Units.567machine # [ 3.781640] systemd[1]: dbus.socket: Deactivated successfully.568machine # [ 3.782994] systemd[1]: Closed D-Bus System Message Bus Socket.569machine # [ 3.788302] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully.570machine # [ 3.790097] systemd[1]: Stopped Find NixOS closure.571machine # [ 3.791204] systemd[1]: Starting Load Kernel Module 9pnet_virtio...572machine # [ 3.792610] systemd[1]: Starting rw-sysroot-nix-store.service...573machine # [ 3.793886] systemd[1]: systemd-sysctl.service: Deactivated successfully.574machine # [ 3.797311] systemd[1]: Stopped Apply Kernel Variables.575machine # [ 3.799817] systemd[1]: systemd-modules-load.service: Deactivated successfully.576machine # [ 3.802179] systemd[1]: Stopped Load Kernel Modules.577machine # [ 3.803227] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully.578machine # [ 3.804838] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root.579machine # [ 3.812488] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.580machine # [ 3.813933] systemd[1]: Stopped Create System Files and Directories.581machine # [ 3.815361] systemd[1]: Stopped target Local File Systems.582machine # [ 3.822880] systemd[1]: Stopped target Preparation for Local File Systems.583machine # [ 3.826128] systemd[1]: systemd-udev-trigger.service: Deactivated successfully.584machine # [ 3.827587] systemd[1]: Stopped Coldplug All udev Devices.585machine # [ 3.828788] systemd[1]: Stopping Rule-based Manager for Device Events and Files...586machine # [ 3.830075] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.587machine # [ 3.831275] systemd[1]: Stopped Virtual Console Setup.588machine # [ 3.832200] systemd[1]: initrd-cleanup.service: Deactivated successfully.589machine # [ 3.833301] systemd[1]: Finished Cleaning Up and Shutting Down Daemons.590machine # [ 3.834388] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.591machine # [ 3.836413] systemd[1]: Finished Load Kernel Module 9pnet_virtio.592machine # [ 3.837476] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.593machine # [ 3.838730] systemd[1]: Finished rw-sysroot-nix-store.service.594machine # [ 3.841583] systemd[1]: systemd-udevd.service: Deactivated successfully.595machine # [ 3.842757] systemd[1]: Stopped Rule-based Manager for Device Events and Files.596machine # [ 3.843962] systemd[1]: systemd-udevd.service: Consumed 1.974s CPU time over 2.148s wall clock time, 28.8M memory peak.597machine # [ 3.845745] systemd[1]: systemd-udevd-control.socket: Deactivated successfully.598machine # [ 3.846903] systemd[1]: Closed udev Control Socket.599machine # [ 3.847732] systemd[1]: Starting Cleanup udev Database...600machine # [ 3.848690] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.601machine # [ 3.849849] systemd[1]: Stopped Create Static Device Nodes in /dev.602machine # [ 3.850821] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully.603machine # [ 3.851966] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully.604machine # [ 3.853033] systemd[1]: kmod-static-nodes.service: Deactivated successfully.605machine # [ 3.853974] systemd[1]: Stopped Create List of Static Device Nodes.606machine # [ 3.914432] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.607machine # [ 3.917499] systemd[1]: Finished Cleanup udev Database.608machine # [ 3.919573] systemd[1]: Reached target Switch Root.609machine # [ 3.921638] systemd[1]: Starting NixOS Activation...610machine # [ 4.151153] initrd-nixos-activation-start[199]: booting system configuration /nix/store/8l3j0y92b9f5chghjjjxpj0d3rgfrh73-nixos-system-machine-test611machine # [ 4.251452] initrd-nixos-activation-start[199]: running activation script...612machine # [ 4.768505] initrd-nixos-activation-start[222]: setting up /etc...613machine # [ 5.105349] systemd[1]: initrd-nixos-activation.service: Deactivated successfully.614machine # [ 5.106774] systemd[1]: Finished NixOS Activation.615machine # [ 5.112188] systemd[1]: Starting Switch Root...616machine # [ 5.137393] systemd[1]: Switching root.617machine # [ 5.255721] systemd-journald[81]: Received SIGTERM from PID 1 (systemd).618machine # [ 5.972687] 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)619machine # [ 5.975274] systemd[1]: Detected virtualization qemu.620machine # [ 5.975436] systemd[1]: Detected architecture arm64.621machine # [ 5.975681] systemd[1]: Detected first boot.622machine # [ 6.005735] systemd[1]: Initializing machine ID from random generator.623machine # [ 6.242249] systemd[1]: bpf-restrict-fs: LSM BPF program attached624machine # [ 6.417884] systemd[1]: Applying preset policy.625machine # [ 6.946663] systemd[1]: Populated /etc with preset unit settings.626machine # [ 7.739222] systemd[1]: initrd-switch-root.service: Deactivated successfully.627machine # [ 7.740732] systemd[1]: Stopped initrd-switch-root.service.628machine # [ 7.749903] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.629machine # [ 7.760659] systemd[1]: Created slice Slice /system/getty.630machine # [ 7.765375] systemd[1]: Created slice User and Session Slice.631machine # [ 7.766304] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.632machine # [ 7.767214] systemd[1]: Started Forward Password Requests to Wall Directory Watch.633machine # [ 7.767657] systemd[1]: Expecting device /dev/hvc0...634machine # [ 7.768259] systemd[1]: Expecting device /dev/ttyAMA0...635machine # [ 7.768960] systemd[1]: Reached target Local Encrypted Volumes.636machine # [ 7.770406] systemd[1]: Stopped target initrd-fs.target.637machine # [ 7.771607] systemd[1]: Stopped target initrd-root-fs.target.638machine # [ 7.772700] systemd[1]: Stopped target initrd-switch-root.target.639machine # [ 7.773762] systemd[1]: Reached target Virtual Machines and Containers.640machine # [ 7.775036] systemd[1]: Reached target Path Units.641machine # [ 7.776161] systemd[1]: Reached target Remote File Systems.642machine # [ 7.777325] systemd[1]: Reached target Slice Units.643machine # [ 7.778445] systemd[1]: Reached target Swaps.644machine # [ 7.801268] systemd[1]: Listening on Query the User Interactively for a Password.645machine # [ 7.819190] systemd[1]: Listening on Process Core Dump Socket.646machine # [ 7.827931] systemd[1]: Listening on Credential Encryption/Decryption.647machine # [ 7.837385] systemd[1]: Listening on Factory Reset Management.648machine # [ 7.839273] systemd[1]: Listening on Hostname Service Socket.649machine # [ 7.854734] systemd[1]: Starting Journal Log Access Socket...650machine # [ 7.857631] systemd[1]: Listening on Journal Audit Socket.651machine # [ 7.867349] systemd[1]: Listening on Console Output Muting Service Socket.652machine # [ 7.869422] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.653machine # [ 7.870699] systemd[1]: TPM PCR Measurements skipped, unmet condition check ConditionSecurity=measured-os654machine # [ 7.871836] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki655machine # [ 7.899884] systemd[1]: Listening on Disk Repartitioning Service Socket.656machine # [ 7.901597] systemd[1]: Listening on udev Control Socket.657machine # [ 7.903341] systemd[1]: Listening on udev Varlink Socket.658machine # [ 7.914078] systemd[1]: Mounting Huge Pages File System...659machine # [ 7.922506] systemd[1]: Mounting POSIX Message Queue File System...660machine # [ 7.938398] systemd[1]: Mounting Kernel Debug File System...661machine # [ 7.966994] systemd[1]: Mounting Kernel Trace File System...662machine # [ 7.981713] systemd[1]: Starting Create List of Static Device Nodes...663machine # [ 7.989473] systemd[1]: Starting Load Kernel Module 9pnet_virtio...664machine # [ 7.992366] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs665machine # [ 8.006433] systemd[1]: Mounting Kernel Configuration File System...666machine # [ 8.011023] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm667machine # [ 8.015271] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore668machine # [ 8.036896] systemd[1]: Starting Load Kernel Module fuse...669machine # [ 8.040675] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67670machine # [ 8.107483] systemd[1]: Starting Journal Service...671machine # [ 8.143474] systemd[1]: Starting Load Kernel Modules...672machine # [ 8.176483] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...673machine # [ 8.183766] systemd[1]: Starting Remount Root and Kernel File Systems...674machine # [ 8.188411] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os675machine # [ 8.195153] systemd[1]: Starting Coldplug All udev Devices...676machine # [ 8.205548] systemd[1]: Listening on Journal Log Access Socket.677machine # [ 8.207928] systemd[1]: Mounted Huge Pages File System.678machine # [ 8.209945] systemd[1]: Mounted POSIX Message Queue File System.679machine # [ 8.211952] systemd[1]: Mounted Kernel Debug File System.680machine # [ 8.213967] systemd[1]: Mounted Kernel Trace File System.681machine # [ 8.216263] systemd[1]: Mounted Kernel Configuration File System.682machine # [ 8.286553] systemd[1]: Finished Create List of Static Device Nodes.683machine # [ 8.300888] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...684machine # [ 8.326504] systemd-journald[293]: Collecting audit messages is enabled.685machine # [ 8.357108] systemd[1]: Finished Load Kernel Modules.686machine # [ 8.367116] EXT4-fs (vda): re-mounted 07df23d9-ffa5-4cf5-8621-4fb43ce52dcb.687machine # [ 8.372699] systemd[1]: Starting Apply Kernel Variables...688machine # [ 8.376848] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.689machine # [ 8.380260] systemd[1]: Finished Load Kernel Module 9pnet_virtio.690machine # [ 8.381306] systemd[1]: Started Journal Service.691machine # [ 8.379636] systemd[1]: Queued start job for default target Multi-User System.692machine # [ 8.386828] systemd[1]: systemd-journald.service: Deactivated successfully.693machine # [ 8.390352] systemd-modules-load[294]: Using 2 probe threads694machine # [ 8.392177] systemd-modules-load[294]: Module 'atkbd' is built in695machine # [ 8.394342] systemd-modules-load[294]: Module 'loop' is built in696machine # [ 8.397608] systemd[1]: Finished Remount Root and Kernel File Systems.697machine # [ 8.399426] systemd[1]: Listening on Disk Image Download Service Socket.698machine # [ 8.402404] systemd[1]: Starting Flush Journal to Persistent Storage...699machine # [ 8.405046] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore700machine # [ 8.412450] systemd[1]: Starting Load/Save OS Random Seed...701machine # [ 8.413893] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os702machine # [ 8.430052] fuse: init (API version 7.45)703machine # [ 8.440841] systemd-oomd[295]: No swap; memory pressure usage will be degraded704machine # [ 8.456641] systemd[1]: modprobe@fuse.service: Deactivated successfully.705machine # [ 8.469615] systemd[1]: Finished Load Kernel Module fuse.706machine # [ 8.484846] systemd[1]: Mounting FUSE Control File System...707machine # [ 8.494234] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.708machine # [ 8.528157] systemd[1]: Mounted FUSE Control File System.709machine # [ 8.565754] systemd-journald[293]: Received client request to flush runtime journal.710machine # [ 8.643500] systemd[1]: Finished Load/Save OS Random Seed.711machine # [ 8.646439] systemd[1]: Reached target First Boot Complete.712machine # [ 8.648601] systemd[1]: Finished Apply Kernel Variables.713machine # [ 8.649830] systemd[1]: Finished Flush Journal to Persistent Storage.714machine # [ 8.668296] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.715machine # [ 8.675813] systemd[1]: Starting Create Static Device Nodes in /dev...716machine # [ 8.765647] systemd[1]: Finished Create Static Device Nodes in /dev.717machine # [ 8.769630] systemd[1]: Reached target Preparation for Local File Systems.718machine # [ 8.779330] systemd[1]: Mounting /run/wrappers...719machine # [ 8.782101] systemd[1]: Starting Rule-based Manager for Device Events and Files...720machine # [ 8.859686] systemd[1]: Mounted /run/wrappers.721machine # [ 8.865394] systemd[1]: Reached target Local File Systems.722machine # [ 8.868243] systemd[1]: Listening on Boot Loader Control Service Socket.723machine # [ 8.876242] systemd[1]: Starting register-nix-paths.service...724machine # [ 8.884188] systemd[1]: Starting Create SUID/SGID Wrappers...725machine # [ 8.895584] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.726machine # [ 8.898728] systemd[1]: Starting Save Transient machine-id to Disk...727machine # [ 8.905384] systemd[1]: Starting Create System Files and Directories...728machine # [ 8.989539] systemd-udevd[327]: Using default interface naming scheme 'v261'.729machine # [ 9.013251] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.730machine # [ 9.019091] systemd[1]: Finished Save Transient machine-id to Disk.731machine # [ 9.100418] systemd[1]: Finished Create System Files and Directories.732machine # [ 9.108588] systemd[1]: Starting Rebuild Journal Catalog...733machine # [ 9.114893] systemd[1]: Starting Record System Boot/Shutdown in UTMP...734machine # [ 9.208926] systemd[1]: Finished Record System Boot/Shutdown in UTMP.735machine # [ 9.255796] systemd[1]: Started Rule-based Manager for Device Events and Files.736machine # [ 9.277755] systemd[1]: Finished Rebuild Journal Catalog.737machine # [ 9.282654] systemd[1]: Starting Update is Completed...738machine # [ 9.365294] systemd[1]: Finished Update is Completed.739machine # [ 9.435508] systemd[1]: Finished Coldplug All udev Devices.740machine # [ 9.658916] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs741machine # [ 9.778418] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.742machine # [ 9.780838] systemd[1]: Finished Create SUID/SGID Wrappers.743machine # [ 9.818648] systemd[1]: Condition check resulted in /dev/hvc0 being skipped.744machine # [ 9.851747] systemd[1]: Condition check resulted in /dev/ttyAMA0 being skipped.745machine # [ 10.044291] systemd[1]: Finished register-nix-paths.service.746machine # [ 10.047455] systemd[1]: Reached target System Initialization.747machine # [ 10.052806] systemd[1]: Started Discard unused filesystem blocks once a week.748machine # [ 10.054046] systemd[1]: Started Daily Cleanup of Temporary Directories.749machine # [ 10.059196] systemd[1]: Reached target Timer Units.750machine # [ 10.065267] systemd[1]: Listening on D-Bus System Message Bus Socket.751machine # [ 10.066280] systemd[1]: Listening on Nix Daemon Socket.752machine # [ 10.071842] systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.753machine # [ 10.080617] systemd[1]: Reached target Socket Units.754machine # [ 10.100398] systemd[1]: Reached target Basic System.755machine # [ 10.101866] systemd[1]: Started backdoor.service.756machine # [ 10.109459] systemd[1]: Starting Import lastlog data into lastlog2 database...757machine # [ 10.115066] systemd[1]: Starting Name Service Cache Daemon (nsncd)...758machine # [ 10.116657] systemd[1]: Starting Post-Boot Actions...759machine # [ 10.117874] systemd[1]: Started Reset console on configuration changes.760machine # [ 10.118897] systemd[1]: Starting resolvconf update...761machine # [ 10.119845] systemd[1]: Started rustfs.service.762machine # [ 10.127657] systemd[1]: Starting rustfs-setup.service...763machine # [ 10.128951] systemd[1]: Starting D-Bus System Message Bus...764machine # [ 10.150570] (udev-worker)[397]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.765machine # [ 10.160853] (udev-worker)[397]: Network interface NamePolicy= disabled on kernel command line.766machine # [ 10.191691] systemd[1]: Finished Post-Boot Actions.767machine # [ 10.198384] (udev-worker)[391]: Network interface NamePolicy= disabled on kernel command line.768machine # connecting to host...769machine # [ 10.243865] nsncd[426]: Sep 08 08:16:55.105 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"770machine # [ 10.257408] systemd[1]: Started Name Service Cache Daemon (nsncd).771machine # [ 10.262434] systemd[1]: Reached target Host and Network Name Lookups.772machine # [ 10.266738] systemd[1]: Reached target User and Group Name Lookups.773machine # [ 10.271368] systemd[1]: Starting User Login Management...774machine: Guest shell says: b'Spawning backdoor root shell...\n'775machine # [ 10.320315] systemd[1]: Finished Import lastlog data into lastlog2 database.776machine: connected to guest root shell777machine: (connecting took 10.65 seconds)778machine: (finished: waiting for the VM to finish booting, in 11.13 seconds)779machine # [ 10.365897] dbus-broker-launch[433]: Looking up NSS user entry for 'systemd-timesync'...780machine # [ 10.401866] dbus-broker-launch[433]: NSS returned no entry for 'systemd-timesync'781machine # [ 10.407451] dbus-broker-launch[433]: Invalid user-name in /nix/store/vz3fis43dvxgbiqz397n6r206b86i7kl-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"782machine # [ 10.447569] systemd[1]: Started D-Bus System Message Bus.783machine # [ 10.513250] dbus-broker-launch[433]: Ready784machine # [ 10.522091] systemd-logind[456]: Watching system buttons on /dev/input/event0 (gpio-keys)785machine # [ 10.537736] systemd-logind[456]: New seat seat0.786machine # [ 10.539329] systemd[1]: Condition check resulted in Virtio network device being skipped.787machine # [ 10.556328] systemd[1]: Stopped target Host and Network Name Lookups.788machine # [ 10.562684] systemd[1]: Stopping Host and Network Name Lookups...789machine # [ 10.563890] systemd[1]: Stopped target User and Group Name Lookups.790machine # [ 10.565827] systemd[1]: Stopping User and Group Name Lookups...791machine # [ 10.567831] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...792machine # [ 10.573899] systemd[1]: Started User Login Management.793machine # [ 10.574705] systemd[1]: Starting linger-users.service...794machine # [ 10.575542] systemd[1]: nscd.service: Deactivated successfully.795machine # [ 10.583766] systemd[1]: Stopped Name Service Cache Daemon (nsncd).796machine # [ 10.585958] systemd[1]: Starting Name Service Cache Daemon (nsncd)...797machine # [ 10.713899] systemd[1]: linger-users.service: Deactivated successfully.798machine # [ 10.717649] systemd[1]: Finished linger-users.service.799machine # [ 10.726975] systemd[1]: Started Name Service Cache Daemon (nsncd).800machine # [ 10.731700] systemd[1]: Reached target Host and Network Name Lookups.801machine # [ 10.738432] nsncd[520]: Sep 08 08:16:55.593 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"802machine # [ 10.746056] systemd[1]: Reached target User and Group Name Lookups.803machine # [ 10.772067] mousedev: PS/2 mouse device common for all mice804machine # [ 10.789560] systemd[1]: Finished resolvconf update.805machine # [ 10.792271] systemd[1]: Reached target Preparation for Network.806machine # [ 10.797982] systemd-logind[456]: Watching system buttons on /dev/input/event1 (QEMU QEMU USB Keyboard)807machine # [ 10.803473] systemd[1]: Starting DHCP Client...808machine # [ 10.806602] systemd[1]: Starting Address configuration of eth1...809machine # [ 10.810454] systemd[1]: Starting Extra networking commands....810machine # [ 11.003124] network-addresses-eth1-start[554]: adding address 192.168.1.1/24... done811machine # [ 11.029247] network-addresses-eth1-start[554]: adding address 2001:db8:1::1/64... done812machine # [ 11.054662] systemd[1]: Finished Address configuration of eth1.813machine # [ 11.097592] dhcpcd[566]: dhcpcd-10.3.2 starting814machine # [ 11.118098] dhcpcd[610]: dev: loaded udev815machine # [ 11.208635] systemd[1]: Finished Extra networking commands..816machine # [ 11.210090] systemd[1]: Reached target Network.817machine # [ 11.247009] systemd[1]: Starting PostgreSQL Server...818machine # [ 11.284064] 8021q: 802.1Q VLAN Support v1.8819machine # [ 11.284569] 8021q: adding VLAN 0 to HW filter on device eth1820machine # [ 11.287471] systemd[1]: Starting Permit User Sessions...821machine # [ 11.396968] cfg80211: Loading compiled-in X.509 certificates for regulatory database822machine # [ 11.435578] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'823machine # [ 11.436132] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'824machine # [ 11.440448] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2825machine # [ 11.440817] cfg80211: failed to load regulatory.db826machine # [ 11.454827] systemd[1]: Finished Permit User Sessions.827machine # [ 11.461651] systemd[1]: Started Getty on tty1.828machine # [ 11.462530] systemd[1]: Reached target Login Prompts.829machine # [ 11.578732] 8021q: adding VLAN 0 to HW filter on device eth0830machine # [ 11.579842] dhcpcd[610]: eth0: waiting for carrier831machine # [ 11.581014] dhcpcd[610]: libudev: received NULL device832machine # [ 11.584534] dhcpcd[610]: libudev: received NULL device833machine # [ 11.586024] dhcpcd[610]: eth0: carrier acquired834machine # [ 11.605924] dhcpcd[610]: DUID 00:01:00:01:32:32:80:f8:52:54:00:12:34:56835machine # [ 11.610479] dhcpcd[610]: eth0: IAID 00:12:34:56836machine # [ 11.611807] dhcpcd[610]: eth0: adding address fe80::5054:ff:fe12:3456837machine # [ 11.741496] postgresql-pre-start[646]: The files belonging to this database system will be owned by user "postgres".838machine # [ 11.747487] postgresql-pre-start[646]: This user must also own the server process.839machine # [ 11.760325] postgresql-pre-start[646]: The database cluster will be initialized with locale "en_US.UTF-8".840machine # [ 11.761806] postgresql-pre-start[646]: The default database encoding has accordingly been set to "UTF8".841machine # [ 11.767522] postgresql-pre-start[646]: The default text search configuration will be set to "english".842machine # [ 11.769244] postgresql-pre-start[646]: Data page checksums are enabled.843machine # [ 11.770141] postgresql-pre-start[646]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok844machine # [ 11.771428] postgresql-pre-start[646]: creating subdirectories ... ok845machine # [ 11.772631] postgresql-pre-start[646]: selecting dynamic shared memory implementation ... posix846machine # [ 11.942489] postgresql-pre-start[646]: selecting default "max_connections" ... 100847machine # [ 12.065485] postgresql-pre-start[646]: selecting default "shared_buffers" ... 128MB848machine # [ 12.336004] input: QEMU Virtio Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:09.0/virtio8/input/input3849machine # [ 12.376298] systemd[1]: Starting Virtual Console Setup...850machine # [ 12.402920] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.851machine # [ 12.409937] systemd[1]: Stopped Virtual Console Setup.852machine # [ 12.414146] systemd[1]: Starting Virtual Console Setup...853machine # [ 12.431460] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.854machine # [ 12.463613] dhcpcd[610]: eth0: soliciting a DHCP lease855machine # [ 12.472872] dhcpcd[610]: eth0: offered 10.0.2.15 from 10.0.2.2856machine # [ 12.475211] systemd-logind[456]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)857machine # [ 12.488445] dhcpcd[610]: eth0: probing address 10.0.2.15/24858machine # [ 12.854321] systemd-vconsole-setup[697]: Configuration of first virtual console was skipped, ignoring remaining ones.859machine # [ 12.857516] systemd[1]: Finished Virtual Console Setup.860machine # [ 14.205673] dhcpcd[610]: eth0: soliciting an IPv6 router861machine # [ 14.206576] dhcpcd[610]: eth0: Router Advertisement from fe80::2862machine # [ 14.207961] dhcpcd[610]: eth0: adding address fec0::5054:ff:fe12:3456/64863machine # [ 14.209081] dhcpcd[610]: eth0: adding route to fec0::/64864machine # [ 14.210037] dhcpcd[610]: eth0: adding default route via fe80::2865machine # [ 14.471588] postgresql-pre-start[646]: selecting default time zone ... UTC866machine # [ 14.476808] postgresql-pre-start[646]: creating configuration files ... ok867machine # [ 14.776445] postgresql-pre-start[646]: running bootstrap script ... ok868machine # [ 15.510260] postgresql-pre-start[646]: performing post-bootstrap initialization ... ok869machine # [ 15.687441] postgresql-pre-start[646]: syncing data to disk ... ok870machine # [ 15.690787] postgresql-pre-start[646]: initdb: warning: enabling "trust" authentication for local connections871machine # [ 15.695346] postgresql-pre-start[646]: 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.872machine # [ 15.702375] postgresql-pre-start[646]: Success. You can now start the database server using:873machine # [ 15.706268] postgresql-pre-start[646]: pg_ctl -D /var/lib/postgresql/18 -l logfile start874machine # [ 15.970988] postgres[734]: [734] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit875machine # [ 15.977097] postgres[734]: [734] LOG: listening on IPv4 address "0.0.0.0", port 5432876machine # [ 15.981003] postgres[734]: [734] LOG: listening on IPv6 address "::", port 5432877machine # [ 15.984232] postgres[734]: [734] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"878machine # [ 16.002587] postgres[743]: [743] LOG: database system was shut down at 2026-09-08 08:17:00 GMT879machine # [ 16.015587] postgres[734]: [734] LOG: database system is ready to accept connections880machine # [ 16.023380] systemd[1]: Started PostgreSQL Server.881machine # [ 16.035533] systemd[1]: Starting PostgreSQL Setup Scripts...882machine # [ 16.344869] postgresql-setup-start[763]: CREATE DATABASE883machine # [ 16.401355] postgresql-setup-start[773]: CREATE ROLE884machine # [ 16.433100] postgresql-setup-start[775]: ALTER DATABASE885machine # [ 16.440316] systemd[1]: Finished PostgreSQL Setup Scripts.886machine # [ 16.442197] systemd[1]: Reached target PostgreSQL.887machine # [ 18.288871] dhcpcd[610]: eth0: leased 10.0.2.15 for 86400 seconds888machine # [ 18.289276] dhcpcd[610]: eth0: adding route to 10.0.2.0/24889machine # [ 18.289466] dhcpcd[610]: eth0: adding default route via 10.0.2.2890machine # [ 18.545502] systemd[1]: Started DHCP Client.891machine # [ 18.547727] systemd[1]: Reached target Network is Online.892machine # [ 18.554211] systemd[1]: Starting k3s service...893machine # [ 18.684930] k3s[852]: time="2026-09-08T08:17:03Z" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock"894machine # [ 18.687602] k3s[852]: time="2026-09-08T08:17:03Z" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/a8fe5a3d6f5f9fe924f026505e933eae420f95b74a871988eda8aaccb37b5334"895machine # [ 23.202313] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Starting k3s 1.35.8+k3s1 (e952d68a)"896machine # [ 23.209426] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Configuring sqlite3 database connection pooling: maxIdle=20, maxOpen=0, maxLifetime=0s, maxIdleTime=2m0s"897machine # [ 23.212344] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Kine built with sqlite from github.com/mattn/go-sqlite3 version 3.53.3"898machine # [ 23.214641] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Configuring database table schema and indexes, this may take a moment..."899machine # [ 23.220145] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Database tables and indexes are up to date"900machine # [ 23.222248] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Running startup VACUUM to reclaim disk space, this may take a moment..."901machine # [ 23.226089] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Startup VACUUM completed successfully"902machine # [ 23.230348] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Kine available at unix://kine.sock"903machine # [ 23.234315] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"904machine # [ 23.237143] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="Datastore connection validated successfully, proceeding with bootstrap data generation"905machine # [ 23.240195] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="generated self-signed CA certificate CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:08.09923164 +0000 UTC notAfter=2036-09-05 07:17:08.09923164 +0000 UTC"906machine # [ 23.244530] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"907machine # [ 23.248469] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=system:k3s-supervisor,O=system:masters signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"908machine # [ 23.252319] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"909machine # [ 23.255849] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"910machine # [ 23.259364] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=system:apiserver,O=system:masters signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"911machine # [ 23.263117] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"912machine # [ 23.266545] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="generated self-signed CA certificate CN=k3s-server-ca@1788855428: notBefore=2026-09-08 07:17:08.10517658 +0000 UTC notAfter=2036-09-05 07:17:08.10517658 +0000 UTC"913machine # [ 23.269848] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"914machine # [ 23.272842] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=kube-scheduler signed by CN=k3s-server-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"915machine # [ 23.275811] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=kube-controller-manager signed by CN=k3s-server-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"916machine # [ 23.279084] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="generated self-signed CA certificate CN=k3s-request-header-ca@1788855428: notBefore=2026-09-08 07:17:08.1078069 +0000 UTC notAfter=2036-09-05 07:17:08.1078069 +0000 UTC"917machine # [ 23.282557] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"918machine # [ 23.285860] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="generated self-signed CA certificate CN=etcd-server-ca@1788855428: notBefore=2026-09-08 07:17:08.10891298 +0000 UTC notAfter=2036-09-05 07:17:08.10891298 +0000 UTC"919machine # [ 23.289113] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"920machine # [ 23.291968] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="generated self-signed CA certificate CN=etcd-peer-ca@1788855428: notBefore=2026-09-08 07:17:08.10989788 +0000 UTC notAfter=2036-09-05 07:17:08.10989788 +0000 UTC"921machine # [ 23.295155] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"922machine # [ 23.297928] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"923machine # [ 23.533390] k3s[852]: time="2026-09-08T08:17:08Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1788855428: notBefore=2026-09-08 07:17:08 +0000 UTC notAfter=2027-09-08 07:17:08 +0000 UTC"924machine # [ 23.545580] k3s[852]: time="2026-09-08T08:17:08Z" level=warning msg="dynamiclistener [::]:6443: no cached certificate available for preload - deferring certificate load until storage initialization or first client request"925machine # [ 23.557178] k3s[852]: time="2026-09-08T08:17:08Z" 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__a63e_f22e_72a2_90f0-a9af22:fec0::a63e:f22e:72a2:90f0 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=350167A3ECEE7A04E3CBAC0D7DD5A508A6BFE157]"926machine # [ 25.117999] k3s[852]: time="2026-09-08T08:17:09Z" level=info msg="Password verified locally for node machine"927machine # [ 25.120580] k3s[852]: time="2026-09-08T08:17:09Z" level=info msg="certificate CN=machine signed by CN=k3s-server-ca@1788855428: notBefore=2026-09-08 07:17:09 +0000 UTC notAfter=2027-09-08 07:17:09 +0000 UTC"928machine # [ 25.770100] k3s[852]: time="2026-09-08T08:17:10Z" level=info msg="certificate CN=system:node:machine,O=system:nodes signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:10 +0000 UTC notAfter=2027-09-08 07:17:10 +0000 UTC"929machine # [ 25.951186] k3s[852]: time="2026-09-08T08:17:10Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:10 +0000 UTC notAfter=2027-09-08 07:17:10 +0000 UTC"930machine # [ 26.074743] k3s[852]: time="2026-09-08T08:17:10Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1788855428: notBefore=2026-09-08 07:17:10 +0000 UTC notAfter=2027-09-08 07:17:10 +0000 UTC"931machine # [ 26.207663] k3s[852]: time="2026-09-08T08:17:11Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:44656: runtime core not ready"932machine # [ 26.403659] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Module overlay was already loaded"933machine # [ 26.508430] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.934machine # [ 26.519890] Bridge firewalling registered935machine # [ 26.543295] k3s[852]: time="2026-09-08T08:17:11Z" level=warning msg="Failed to load kernel module iptable_nat with modprobe"936machine # [ 26.565446] k3s[852]: time="2026-09-08T08:17:11Z" level=warning msg="Failed to load kernel module iptable_filter with modprobe"937machine # [ 26.589892] k3s[852]: time="2026-09-08T08:17:11Z" level=warning msg="Failed to load kernel module nft-expr-counter with modprobe"938machine # [ 26.675116] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_close_wait' to 3600"939machine # [ 26.678073] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Set sysctl 'net/ipv4/conf/all/forwarding' to 1"940machine # [ 26.680099] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_max' to 131072"941machine # [ 26.682274] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400"942machine # [ 26.691318] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Creating k3s-cert-monitor event broadcaster"943machine # [ 26.695889] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Polling for API server readiness: GET /readyz failed: the server is currently unable to handle the request"944machine # [ 26.708226] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Connecting to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"945machine # [ 26.709971] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Handling backend connection request [machine]"946machine # [ 26.716259] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Saving cluster bootstrap data to datastore"947machine # [ 26.717895] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"948machine # [ 26.719488] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"949machine # [ 26.722753] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Remotedialer connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"950machine # [ 26.724685] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Connection to etcd is ready"951machine # [ 26.725876] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="ETCD server is now running"952machine # [ 26.727091] k3s[852]: time="2026-09-08T08:17:11Z" 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"953machine # [ 26.761373] k3s[852]: time="2026-09-08T08:17:11Z" 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"954machine # [ 26.771365] k3s[852]: time="2026-09-08T08:17:11Z" 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"955machine # [ 26.791528] k3s[852]: time="2026-09-08T08:17:11Z" 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"956machine # [ 26.808379] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"957machine # [ 26.810053] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="To join server node to cluster: k3s server -s https://10.0.2.15:6443 -t ${SERVER_NODE_TOKEN}"958machine # [ 26.811940] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"959machine # [ 26.815024] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="To join agent node to cluster: k3s agent -s https://10.0.2.15:6443 -t ${AGENT_NODE_TOKEN}"960machine # [ 26.818795] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"961machine # [ 26.821439] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Run: k3s kubectl"962machine # [ 26.823686] k3s[852]: I0908 08:17:11.618816 852 options.go:263] external host was not specified, using 10.0.2.15963machine # [ 26.828543] k3s[852]: I0908 08:17:11.624151 852 server.go:158] Version: v1.35.8+k3s1964machine # [ 26.836123] k3s[852]: I0908 08:17:11.624223 852 server.go:160] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""965machine # [ 26.866572] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log"966machine # [ 26.883022] k3s[852]: time="2026-09-08T08:17:11Z" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml"967machine # [ 26.983031] k3s[852]: time="2026-09-08T08:17:11Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:44728: runtime core not ready"968machine # [ 27.153878] k3s[852]: time="2026-09-08T08:17:12Z" 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"969machine # [ 27.228439] k3s[852]: I0908 08:17:12.092334 852 shared_informer.go:349] "Waiting for caches to sync" controller="node_authorizer"970machine # [ 27.236564] k3s[852]: I0908 08:17:12.101017 852 shared_informer.go:370] "Waiting for caches to sync"971machine # [ 27.239677] k3s[852]: I0908 08:17:12.104185 852 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.972machine # [ 27.248763] k3s[852]: I0908 08:17:12.104236 852 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.973machine # [ 27.256924] k3s[852]: I0908 08:17:12.104782 852 instance.go:240] Using reconciler: lease974machine # [ 27.258118] k3s[852]: I0908 08:17:12.116159 852 handler.go:304] Adding GroupVersion apiextensions.k8s.io v1 to ResourceManager975machine # [ 27.259609] k3s[852]: W0908 08:17:12.116198 852 genericapiserver.go:787] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources.976machine # [ 27.262010] k3s[852]: I0908 08:17:12.120365 852 cidrallocator.go:198] starting ServiceCIDR Allocator Controller977machine # [ 27.329807] k3s[852]: I0908 08:17:12.194255 852 handler.go:304] Adding GroupVersion v1 to ResourceManager978machine # [ 27.331841] k3s[852]: I0908 08:17:12.194663 852 apis.go:112] API group "internal.apiserver.k8s.io" is not enabled, skipping.979machine # [ 27.378172] k3s[852]: I0908 08:17:12.242671 852 apis.go:112] API group "storagemigration.k8s.io" is not enabled, skipping.980machine # [ 27.463514] k3s[852]: I0908 08:17:12.327947 852 handler.go:304] Adding GroupVersion authentication.k8s.io v1 to ResourceManager981machine # [ 27.465554] k3s[852]: W0908 08:17:12.328196 852 genericapiserver.go:787] Skipping API authentication.k8s.io/v1beta1 because it has no resources.982machine # [ 27.467403] k3s[852]: W0908 08:17:12.328219 852 genericapiserver.go:787] Skipping API authentication.k8s.io/v1alpha1 because it has no resources.983machine # [ 27.469363] k3s[852]: I0908 08:17:12.329031 852 handler.go:304] Adding GroupVersion authorization.k8s.io v1 to ResourceManager984machine # [ 27.471024] k3s[852]: W0908 08:17:12.329054 852 genericapiserver.go:787] Skipping API authorization.k8s.io/v1beta1 because it has no resources.985machine # [ 27.473079] k3s[852]: I0908 08:17:12.330017 852 handler.go:304] Adding GroupVersion autoscaling v2 to ResourceManager986machine # [ 27.474616] k3s[852]: I0908 08:17:12.331020 852 handler.go:304] Adding GroupVersion autoscaling v1 to ResourceManager987machine # [ 27.476237] k3s[852]: W0908 08:17:12.331046 852 genericapiserver.go:787] Skipping API autoscaling/v2beta1 because it has no resources.988machine # [ 27.478016] k3s[852]: W0908 08:17:12.331055 852 genericapiserver.go:787] Skipping API autoscaling/v2beta2 because it has no resources.989machine # [ 27.479751] k3s[852]: I0908 08:17:12.332829 852 handler.go:304] Adding GroupVersion batch v1 to ResourceManager990machine # [ 27.481349] k3s[852]: W0908 08:17:12.332855 852 genericapiserver.go:787] Skipping API batch/v1beta1 because it has no resources.991machine # [ 27.483033] k3s[852]: I0908 08:17:12.333746 852 handler.go:304] Adding GroupVersion certificates.k8s.io v1 to ResourceManager992machine # [ 27.484856] k3s[852]: W0908 08:17:12.333763 852 genericapiserver.go:787] Skipping API certificates.k8s.io/v1beta1 because it has no resources.993machine # [ 27.486938] k3s[852]: W0908 08:17:12.333770 852 genericapiserver.go:787] Skipping API certificates.k8s.io/v1alpha1 because it has no resources.994machine # [ 27.490624] k3s[852]: I0908 08:17:12.334563 852 handler.go:304] Adding GroupVersion coordination.k8s.io v1 to ResourceManager995machine # [ 27.492499] k3s[852]: W0908 08:17:12.334580 852 genericapiserver.go:787] Skipping API coordination.k8s.io/v1beta1 because it has no resources.996machine # [ 27.494736] k3s[852]: W0908 08:17:12.334587 852 genericapiserver.go:787] Skipping API coordination.k8s.io/v1alpha2 because it has no resources.997machine # [ 27.496509] k3s[852]: I0908 08:17:12.335151 852 handler.go:304] Adding GroupVersion discovery.k8s.io v1 to ResourceManager998machine # [ 27.498136] k3s[852]: W0908 08:17:12.335166 852 genericapiserver.go:787] Skipping API discovery.k8s.io/v1beta1 because it has no resources.999machine # [ 27.499780] k3s[852]: I0908 08:17:12.338053 852 handler.go:304] Adding GroupVersion networking.k8s.io v1 to ResourceManager1000machine # [ 27.501482] k3s[852]: W0908 08:17:12.338082 852 genericapiserver.go:787] Skipping API networking.k8s.io/v1beta1 because it has no resources.1001machine # [ 27.503275] k3s[852]: I0908 08:17:12.338568 852 handler.go:304] Adding GroupVersion node.k8s.io v1 to ResourceManager1002machine # [ 27.504916] k3s[852]: W0908 08:17:12.338580 852 genericapiserver.go:787] Skipping API node.k8s.io/v1beta1 because it has no resources.1003machine # [ 27.506663] k3s[852]: W0908 08:17:12.338587 852 genericapiserver.go:787] Skipping API node.k8s.io/v1alpha1 because it has no resources.1004machine # [ 27.508813] k3s[852]: I0908 08:17:12.339490 852 handler.go:304] Adding GroupVersion policy v1 to ResourceManager1005machine # [ 27.510772] k3s[852]: W0908 08:17:12.339508 852 genericapiserver.go:787] Skipping API policy/v1beta1 because it has no resources.1006machine # [ 27.512621] k3s[852]: I0908 08:17:12.341321 852 handler.go:304] Adding GroupVersion rbac.authorization.k8s.io v1 to ResourceManager1007machine # [ 27.514265] k3s[852]: W0908 08:17:12.341341 852 genericapiserver.go:787] Skipping API rbac.authorization.k8s.io/v1beta1 because it has no resources.1008machine # [ 27.516249] k3s[852]: W0908 08:17:12.341349 852 genericapiserver.go:787] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources.1009machine # [ 27.518158] k3s[852]: I0908 08:17:12.341826 852 handler.go:304] Adding GroupVersion scheduling.k8s.io v1 to ResourceManager1010machine # [ 27.519640] k3s[852]: W0908 08:17:12.341839 852 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1beta1 because it has no resources.1011machine # [ 27.521636] k3s[852]: W0908 08:17:12.341845 852 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources.1012machine # [ 27.523435] k3s[852]: I0908 08:17:12.345316 852 handler.go:304] Adding GroupVersion storage.k8s.io v1 to ResourceManager1013machine # [ 27.525153] k3s[852]: W0908 08:17:12.345364 852 genericapiserver.go:787] Skipping API storage.k8s.io/v1beta1 because it has no resources.1014machine # [ 27.527021] k3s[852]: W0908 08:17:12.345374 852 genericapiserver.go:787] Skipping API storage.k8s.io/v1alpha1 because it has no resources.1015machine # [ 27.529235] k3s[852]: I0908 08:17:12.347240 852 handler.go:304] Adding GroupVersion flowcontrol.apiserver.k8s.io v1 to ResourceManager1016machine # [ 27.530979] k3s[852]: W0908 08:17:12.347264 852 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta3 because it has no resources.1017machine # [ 27.533104] k3s[852]: W0908 08:17:12.347270 852 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta2 because it has no resources.1018machine # [ 27.538554] k3s[852]: W0908 08:17:12.347277 852 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta1 because it has no resources.1019machine # [ 27.541072] k3s[852]: I0908 08:17:12.351160 852 handler.go:304] Adding GroupVersion apps v1 to ResourceManager1020machine # [ 27.542787] k3s[852]: W0908 08:17:12.351187 852 genericapiserver.go:787] Skipping API apps/v1beta2 because it has no resources.1021machine # [ 27.544461] k3s[852]: W0908 08:17:12.351195 852 genericapiserver.go:787] Skipping API apps/v1beta1 because it has no resources.1022machine # [ 27.546233] k3s[852]: I0908 08:17:12.353022 852 handler.go:304] Adding GroupVersion admissionregistration.k8s.io v1 to ResourceManager1023machine # [ 27.547894] k3s[852]: W0908 08:17:12.353055 852 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources.1024machine # [ 27.549934] k3s[852]: W0908 08:17:12.353062 852 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources.1025machine # [ 27.551767] k3s[852]: I0908 08:17:12.353694 852 handler.go:304] Adding GroupVersion events.k8s.io v1 to ResourceManager1026machine # [ 27.553406] k3s[852]: W0908 08:17:12.353731 852 genericapiserver.go:787] Skipping API events.k8s.io/v1beta1 because it has no resources.1027machine # [ 27.555068] k3s[852]: I0908 08:17:12.356102 852 handler.go:304] Adding GroupVersion resource.k8s.io v1 to ResourceManager1028machine # [ 27.556716] k3s[852]: W0908 08:17:12.356131 852 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta2 because it has no resources.1029machine # [ 27.558733] k3s[852]: W0908 08:17:12.356139 852 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta1 because it has no resources.1030machine # [ 27.560415] k3s[852]: W0908 08:17:12.356145 852 genericapiserver.go:787] Skipping API resource.k8s.io/v1alpha3 because it has no resources.1031machine # [ 27.562025] k3s[852]: I0908 08:17:12.360436 852 handler.go:304] Adding GroupVersion apiregistration.k8s.io v1 to ResourceManager1032machine # [ 27.563526] k3s[852]: W0908 08:17:12.360461 852 genericapiserver.go:787] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources.1033machine # [ 27.911751] k3s[852]: time="2026-09-08T08:17:12Z" level=info msg="containerd is now running"1034machine # [ 27.918484] k3s[852]: time="2026-09-08T08:17:12Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/k3s-airgap-images-arm64.tar.zst"1035machine # [ 28.131948] k3s[852]: I0908 08:17:12.996289 852 secure_serving.go:211] Serving securely on 127.0.0.1:64441036machine # [ 28.136680] k3s[852]: I0908 08:17:12.997170 852 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"1037machine # [ 28.143177] k3s[852]: I0908 08:17:12.997385 852 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"1038machine # [ 28.148300] k3s[852]: I0908 08:17:12.997514 852 tlsconfig.go:243] "Starting DynamicServingCertificateController"1039machine # [ 28.152714] k3s[852]: time="2026-09-08T08:17:12Z" level=info msg="Starting legacy_token_tracking_controller" logger=k3s1040machine # [ 28.158461] k3s[852]: time="2026-09-08T08:17:12Z" level=info msg="Waiting for caches to sync" logger=k3s1041machine # [ 28.161174] k3s[852]: I0908 08:17:12.998151 852 remote_available_controller.go:425] Starting RemoteAvailability controller1042machine # [ 28.167467] k3s[852]: I0908 08:17:12.998165 852 cache.go:32] Waiting for caches to sync for RemoteAvailability controller1043machine # [ 28.171409] k3s[852]: I0908 08:17:12.998211 852 aggregator.go:185] waiting for initial CRD sync...1044machine # [ 28.180550] k3s[852]: I0908 08:17:12.998227 852 controller.go:78] Starting OpenAPI AggregationController1045machine # [ 28.183536] k3s[852]: I0908 08:17:13.000204 852 system_namespaces_controller.go:66] Starting system namespaces controller1046machine # [ 28.189918] k3s[852]: I0908 08:17:13.000922 852 cluster_authentication_trust_controller.go:459] Starting cluster_authentication_trust_controller controller1047machine # [ 28.194495] k3s[852]: time="2026-09-08T08:17:13Z" level=info msg="Waiting for caches to sync" logger=k3s1048machine # [ 28.197015] k3s[852]: I0908 08:17:13.002185 852 controller.go:113] "Deleting old lease on startup" lease="kube-system/apiserver-ik4pcwfs7qgdl76byc4pomgvia"1049machine # [ 28.200403] k3s[852]: I0908 08:17:13.002468 852 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"1050machine # [ 28.204977] k3s[852]: time="2026-09-08T08:17:13Z" level=info msg="Starting apiserver lease garbage collector" logger=k3s1051machine # [ 28.206464] k3s[852]: time="2026-09-08T08:17:13Z" level=info msg="Waiting for caches to sync" logger=k3s1052machine # [ 28.208525] k3s[852]: I0908 08:17:13.003521 852 apiservice_controller.go:100] Starting APIServiceRegistrationController1053machine # [ 28.216882] k3s[852]: I0908 08:17:13.003536 852 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller1054machine # [ 28.222125] k3s[852]: I0908 08:17:13.003562 852 apf_controller.go:377] Starting API Priority and Fairness config controller1055machine # [ 28.225359] k3s[852]: I0908 08:17:13.004236 852 customresource_discovery_controller.go:294] Starting DiscoveryController1056machine # [ 28.231436] k3s[852]: I0908 08:17:13.004338 852 local_available_controller.go:156] Starting LocalAvailability controller1057machine # [ 28.234042] k3s[852]: I0908 08:17:13.004393 852 cache.go:32] Waiting for caches to sync for LocalAvailability controller1058machine # [ 28.235628] k3s[852]: I0908 08:17:13.004421 852 controller.go:80] Starting OpenAPI V3 AggregationController1059machine # [ 28.238078] k3s[852]: I0908 08:17:13.004477 852 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"1060machine # [ 28.243780] k3s[852]: I0908 08:17:13.006539 852 crdregistration_controller.go:114] Starting crd-autoregister controller1061machine # [ 28.250844] k3s[852]: I0908 08:17:13.006566 852 shared_informer.go:349] "Waiting for caches to sync" controller="crd-autoregister"1062machine # [ 28.256168] k3s[852]: I0908 08:17:13.009677 852 default_servicecidr_controller.go:110] Starting kubernetes-service-cidr-controller1063machine # [ 28.259423] k3s[852]: I0908 08:17:13.009736 852 shared_informer.go:349] "Waiting for caches to sync" controller="kubernetes-service-cidr-controller"1064machine # [ 28.262427] k3s[852]: I0908 08:17:13.009821 852 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"1065machine # [ 28.266292] k3s[852]: I0908 08:17:13.009975 852 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"1066machine # [ 28.270835] k3s[852]: I0908 08:17:13.010666 852 repairip.go:210] Starting ipallocator-repair-controller1067machine # [ 28.276286] k3s[852]: I0908 08:17:13.010683 852 shared_informer.go:349] "Waiting for caches to sync" controller="ipallocator-repair-controller"1068machine # [ 28.278025] k3s[852]: I0908 08:17:13.034100 852 controller.go:142] Starting OpenAPI controller1069machine # [ 28.279340] k3s[852]: I0908 08:17:13.034260 852 controller.go:90] Starting OpenAPI V3 controller1070machine # [ 28.280715] k3s[852]: I0908 08:17:13.034284 852 naming_controller.go:305] Starting NamingConditionController1071machine # [ 28.282165] k3s[852]: I0908 08:17:13.034364 852 nonstructuralschema_controller.go:202] Starting NonStructuralSchemaConditionController1072machine # [ 28.286156] k3s[852]: I0908 08:17:13.034391 852 apiapproval_controller.go:196] Starting KubernetesAPIApprovalPolicyConformantConditionController1073machine # [ 28.288091] k3s[852]: I0908 08:17:13.034405 852 crd_finalizer.go:273] Starting CRDFinalizer1074machine # [ 28.308302] rustfs-setup-start[933]: mb s3://niks31075machine # [ 28.312693] systemd[1]: Finished rustfs-setup.service.1076machine # [ 28.436120] k3s[852]: time="2026-09-08T08:17:13Z" level=info msg="Caches are synced" logger=k3s1077machine # [ 28.437566] k3s[852]: I0908 08:17:13.300269 852 cache.go:39] Caches are synced for RemoteAvailability controller1078machine # [ 28.444534] k3s[852]: time="2026-09-08T08:17:13Z" level=info msg="Caches are synced" logger=k3s1079machine # [ 28.445861] k3s[852]: I0908 08:17:13.309396 852 cache.go:39] Caches are synced for APIServiceRegistrationController controller1080machine # [ 28.447397] k3s[852]: I0908 08:17:13.309447 852 apf_controller.go:382] Running API Priority and Fairness config worker1081machine # [ 28.448919] k3s[852]: I0908 08:17:13.309457 852 apf_controller.go:385] Running API Priority and Fairness periodic rebalancing process1082machine # [ 28.450492] k3s[852]: I0908 08:17:13.309911 852 shared_informer.go:356] "Caches are synced" controller="kubernetes-service-cidr-controller"1083machine # [ 28.456112] k3s[852]: I0908 08:17:13.309950 852 default_servicecidr_controller.go:169] Creating default ServiceCIDR with CIDRs: [10.43.0.0/16]1084machine # [ 28.457919] k3s[852]: I0908 08:17:13.310187 852 cache.go:39] Caches are synced for LocalAvailability controller1085machine # [ 28.459406] k3s[852]: I0908 08:17:13.310808 852 shared_informer.go:356] "Caches are synced" controller="ipallocator-repair-controller"1086machine # [ 28.463526] k3s[852]: time="2026-09-08T08:17:13Z" level=info msg="Caches are synced" logger=k3s1087machine # [ 28.464827] k3s[852]: I0908 08:17:13.312580 852 handler_discovery.go:451] Starting ResourceDiscoveryManager1088machine # [ 28.466131] k3s[852]: I0908 08:17:13.313740 852 shared_informer.go:356] "Caches are synced" controller="crd-autoregister"1089machine # [ 28.467579] k3s[852]: I0908 08:17:13.313805 852 aggregator.go:187] initial CRD sync complete...1090machine # [ 28.473198] k3s[852]: I0908 08:17:13.313819 852 autoregister_controller.go:144] Starting autoregister controller1091machine # [ 28.474645] k3s[852]: I0908 08:17:13.313831 852 cache.go:32] Waiting for caches to sync for autoregister controller1092machine # [ 28.478730] k3s[852]: I0908 08:17:13.313843 852 cache.go:39] Caches are synced for autoregister controller1093machine # [ 28.482582] k3s[852]: I0908 08:17:13.317842 852 shared_informer.go:356] "Caches are synced" controller="node_authorizer"1094machine # [ 28.484245] k3s[852]: I0908 08:17:13.318712 852 shared_informer.go:377] "Caches are synced"1095machine # [ 28.485408] k3s[852]: I0908 08:17:13.318755 852 policy_source.go:248] refreshing policies1096machine # [ 28.488259] k3s[852]: I0908 08:17:13.329145 852 controller.go:667] quota admission added evaluator for: namespaces1097machine # [ 28.493550] k3s[852]: I0908 08:17:13.357988 852 controller.go:667] quota admission added evaluator for: leases.coordination.k8s.io1098machine # [ 28.522867] k3s[852]: E0908 08:17:13.386144 852 controller.go:95] Unable to perform initial Kubernetes service initialization: namespaces "default" not found1099machine # [ 28.560179] k3s[852]: I0908 08:17:13.424401 852 cidrallocator.go:302] created ClusterIP allocator for Service CIDR 10.43.0.0/161100machine # [ 28.564099] k3s[852]: I0908 08:17:13.428577 852 default_servicecidr_controller.go:231] Setting default ServiceCIDR condition Ready to True1101machine # [ 28.575891] k3s[852]: I0908 08:17:13.440387 852 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161102machine # [ 28.684173] k3s[852]: time="2026-09-08T08:17:13Z" level=info msg="Polling for API server readiness: GET /readyz failed: unknown"1103machine # [ 29.140291] k3s[852]: I0908 08:17:14.004702 852 storage_scheduling.go:123] created PriorityClass system-node-critical with value 20000010001104machine # [ 29.143796] k3s[852]: I0908 08:17:14.007936 852 storage_scheduling.go:123] created PriorityClass system-cluster-critical with value 20000000001105machine # [ 29.146556] k3s[852]: I0908 08:17:14.007954 852 storage_scheduling.go:139] all system priority classes are created successfully or already exist.1106machine # [ 29.911490] k3s[852]: I0908 08:17:14.775302 852 controller.go:667] quota admission added evaluator for: roles.rbac.authorization.k8s.io1107machine # [ 29.952104] k3s[852]: I0908 08:17:14.815311 852 controller.go:667] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io1108machine # [ 30.037917] k3s[852]: I0908 08:17:14.901857 852 alloc.go:329] "allocated clusterIPs" service="default/kubernetes" clusterIPs={"IPv4":"10.43.0.1"}1109machine # [ 30.039894] k3s[852]: E0908 08:17:14.903097 852 repairip.go:372] "Unhandled Error" err="the ClusterIP [IPv4]: 10.43.0.1 for Service default/kubernetes is not allocated; repairing" logger="UnhandledError"1110machine # [ 30.054999] k3s[852]: W0908 08:17:14.919516 852 lease.go:265] Resetting endpoints for master service "kubernetes" to [10.0.2.15]1111machine # [ 30.059501] k3s[852]: I0908 08:17:14.921342 852 controller.go:667] quota admission added evaluator for: endpoints1112machine # [ 30.061727] k3s[852]: I0908 08:17:14.926261 852 controller.go:667] quota admission added evaluator for: endpointslices.discovery.k8s.io1113machine # [ 30.709627] k3s[852]: time="2026-09-08T08:17:15Z" level=info msg="Creating k3s-supervisor event broadcaster"1114machine # [ 30.712370] k3s[852]: time="2026-09-08T08:17:15Z" level=info msg="Waiting for untainted node"1115machine # [ 30.713886] k3s[852]: time="2026-09-08T08:17:15Z" level=info msg="Kube API server is now running"1116machine # [ 30.715041] k3s[852]: time="2026-09-08T08:17:15Z" level=info msg="k3s is up and running"1117machine # [ 30.720702] systemd[1]: Started k3s service.1118machine # [ 30.721811] systemd[1]: Reached target Multi-User System.1119machine # [ 30.722920] systemd[1]: Startup finished in 701ms (kernel) + 4.710s (initrd) + 25.304s (userspace) = 30.716s.1120machine # [ 30.725723] k3s[852]: time="2026-09-08T08:17:15Z" 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=Normal1121machine # [ 30.742751] k3s[852]: I0908 08:17:15.607216 852 controllermanager.go:189] "Starting" version="v1.35.8+k3s1"1122machine # [ 30.745205] k3s[852]: I0908 08:17:15.609750 852 controllermanager.go:191] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1123machine # [ 30.752331] k3s[852]: I0908 08:17:15.616833 852 secure_serving.go:211] Serving securely on 127.0.0.1:102571124machine # [ 30.755362] k3s[852]: I0908 08:17:15.619394 852 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1125machine # [ 30.757756] k3s[852]: I0908 08:17:15.619451 852 shared_informer.go:370] "Waiting for caches to sync"1126machine # [ 30.759366] k3s[852]: I0908 08:17:15.619715 852 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"1127machine # [ 30.763228] k3s[852]: I0908 08:17:15.619970 852 tlsconfig.go:243] "Starting DynamicServingCertificateController"1128machine # [ 30.764609] k3s[852]: I0908 08:17:15.620449 852 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1129machine # [ 30.766838] k3s[852]: I0908 08:17:15.620714 852 shared_informer.go:370] "Waiting for caches to sync"1130machine # [ 30.768799] k3s[852]: I0908 08:17:15.620756 852 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1131machine # [ 30.771681] k3s[852]: I0908 08:17:15.620773 852 shared_informer.go:370] "Waiting for caches to sync"1132machine # [ 30.789699] k3s[852]: I0908 08:17:15.654098 852 controller.go:667] quota admission added evaluator for: serviceaccounts1133machine # [ 30.875589] k3s[852]: I0908 08:17:15.739673 852 shared_informer.go:370] "Waiting for caches to sync"1134machine # [ 31.235586] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Creating embedded CRD etcdsnapshotfiles.k3s.cattle.io"1135machine # [ 31.239656] k3s[852]: I0908 08:17:16.104162 852 range_allocator.go:113] "No Secondary Service CIDR provided. Skipping filtering out secondary service addresses" logger="node-ipam-controller"1136machine # [ 31.243941] k3s[852]: I0908 08:17:16.106738 852 controllermanager.go:627] "Warning: controller is disabled" controller="cloud-node-lifecycle-controller"1137machine # [ 31.248113] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Creating embedded CRD addons.k3s.cattle.io"1138machine # [ 31.257609] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Creating embedded CRD helmchartconfigs.helm.cattle.io"1139machine # [ 31.259247] k3s[852]: I0908 08:17:16.121445 852 shared_informer.go:377] "Caches are synced"1140machine # [ 31.261072] k3s[852]: I0908 08:17:16.121659 852 shared_informer.go:377] "Caches are synced"1141machine # [ 31.262400] k3s[852]: I0908 08:17:16.121784 852 shared_informer.go:377] "Caches are synced"1142machine # [ 31.275301] k3s[852]: I0908 08:17:16.139796 852 shared_informer.go:377] "Caches are synced"1143machine # [ 31.279809] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Creating embedded CRD helmcharts.helm.cattle.io"1144machine # [ 31.307751] k3s[852]: I0908 08:17:16.171731 852 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1145machine # [ 31.315905] k3s[852]: I0908 08:17:16.180421 852 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1146machine # [ 31.325401] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available"1147machine # [ 31.330307] k3s[852]: I0908 08:17:16.194827 852 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1148machine # [ 31.332809] k3s[852]: I0908 08:17:16.197338 852 controllermanager.go:627] "Warning: controller is disabled" controller="service-lb-controller"1149machine # [ 31.370785] k3s[852]: I0908 08:17:16.233238 852 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1150machine # [ 31.406700] k3s[852]: I0908 08:17:16.271191 852 controllermanager.go:627] "Warning: controller is disabled" controller="bootstrap-signer-controller"1151machine # [ 31.411909] k3s[852]: I0908 08:17:16.271225 852 controllermanager.go:627] "Warning: controller is disabled" controller="node-route-controller"1152machine # [ 31.499159] k3s[852]: I0908 08:17:16.363473 852 node_lifecycle_controller.go:419] "Controller will reconcile labels" logger="node-lifecycle-controller"1153machine: (finished: waiting for unit k3s.service, in 32.31 seconds)1154machine: waiting for unit rustfs-setup.service1155machine: (finished: waiting for unit rustfs-setup.service, in 0.09 seconds)1156machine: waiting for unit postgresql.service1157machine # [ 31.650087] k3s[852]: I0908 08:17:16.514580 852 controllermanager.go:579] "Warning: skipping controller" controller="storage-version-migrator-controller"1158machine # [ 31.652954] k3s[852]: I0908 08:17:16.516677 852 controllermanager.go:627] "Warning: controller is disabled" controller="selinux-warning-controller"1159machine: (finished: waiting for unit postgresql.service, in 0.14 seconds)1160subtest: chart deploys and becomes ready1161??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1162 File "/nix/store/ifid8v1phbdldw2n5l1p1v3an4s9p3q8-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391163machine: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s1164??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1165 File "/nix/store/ifid8v1phbdldw2n5l1p1v3an4s9p3q8-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391166machine # [ 31.850809] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available"1167machine # [ 31.856098] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-40.1.4+up40.1.0.tgz"1168machine # [ 31.860601] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-40.1.4+up40.1.0.tgz"1169machine # [ 31.864444] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml"1170machine # [ 31.867762] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml"1171machine # [ 31.871259] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml"1172machine # [ 31.873410] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml"1173machine # [ 31.877676] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/runtimes.yaml"1174machine # [ 31.881688] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml"1175machine # [ 32.049095] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Starting dynamiclistener CN filter node controller with SANs: [127.0.0.1 ::1 localhost machine 10.0.2.15 fec0::a63e:f22e:72a2:90f0 10.43.0.1 kubernetes kubernetes.default kubernetes.default.svc kubernetes.default.svc.cluster.local]"1176machine # [ 32.053536] k3s[852]: time="2026-09-08T08:17:16Z" level=info msg="Tunnel server egress proxy mode: agent"1177machine # Error from server (NotFound): namespaces "niks3" not found1178machine # [ 32.261168] k3s[852]: I0908 08:17:17.125080 852 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="storageversion-garbage-collector-controller" requiredFeatureGates=["APIServerIdentity","StorageVersionAPI"]1179machine # [ 32.263938] k3s[852]: I0908 08:17:17.125146 852 controllermanager.go:579] "Warning: skipping controller" controller="storageversion-garbage-collector-controller"1180machine # [ 32.539588] k3s[852]: time="2026-09-08T08:17:17Z" 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__a63e_f22e_72a2_90f0-a9af22:fec0::a63e:f22e:72a2:90f0 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=350167A3ECEE7A04E3CBAC0D7DD5A508A6BFE157]"1181machine # [ 32.561079] k3s[852]: I0908 08:17:17.425440 852 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="podcertificaterequest-cleaner-controller" requiredFeatureGates=["PodCertificateRequest"]1182machine # [ 32.563739] k3s[852]: I0908 08:17:17.425485 852 controllermanager.go:579] "Warning: skipping controller" controller="podcertificaterequest-cleaner-controller"1183machine # [ 32.568419] k3s[852]: time="2026-09-08T08:17:17Z" level=info msg="Active TLS secret kube-system/k3s-serving (ver=237) (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__a63e_f22e_72a2_90f0-a9af22:fec0::a63e:f22e:72a2:90f0 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=350167A3ECEE7A04E3CBAC0D7DD5A508A6BFE157]"1184machine # [ 33.165333] k3s[852]: time="2026-09-08T08:17:18Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller"1185machine # [ 33.168450] k3s[852]: time="2026-09-08T08:17:18Z" level=info msg="Creating deploy event broadcaster"1186machine # [ 33.174329] k3s[852]: I0908 08:17:18.038812 852 controller.go:667] quota admission added evaluator for: addons.k3s.cattle.io1187machine # [ 33.184072] k3s[852]: time="2026-09-08T08:17:18Z" level=info msg="Starting /v1, Kind=Node controller"1188machine # [ 33.185795] k3s[852]: time="2026-09-08T08:17:18Z" level=info msg="Creating helm-controller event broadcaster"1189machine # [ 33.204818] k3s[852]: time="2026-09-08T08:17:18Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1190machine # [ 33.207402] k3s[852]: time="2026-09-08T08:17:18Z" 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=Normal1191machine # [ 33.242509] k3s[852]: time="2026-09-08T08:17:18Z" level=info msg="Cluster dns configmap has been set successfully"1192machine # Error from server (NotFound): namespaces "niks3" not found1193machine # [ 33.609004] k3s[852]: time="2026-09-08T08:17:18Z" 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=Normal1194machine # [ 35.085409] k3s[852]: time="2026-09-08T08:17:19Z" 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=Normal1195machine # [ 35.192337] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1196machine # [ 35.600220] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1197machine # [ 35.701868] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Starting rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding controller"1198machine # [ 35.708313] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Starting batch/v1, Kind=Job controller"1199machine # [ 35.711018] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Starting /v1, Kind=Secret controller"1200machine # [ 35.716346] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Starting /v1, Kind=ConfigMap controller"1201machine # [ 35.718936] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Starting /v1, Kind=ServiceAccount controller"1202machine # [ 35.724424] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller"1203machine # [ 35.731242] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller"1204machine # [ 35.738247] k3s[852]: W0908 08:17:20.592836 852 probe.go:272] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating.1205machine # [ 35.745380] k3s[852]: time="2026-09-08T08:17:20Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Deferred node password secret validation complete" object=machine reason=NodePasswordValidationComplete type=Normal1206machine # [ 35.827003] k3s[852]: time="2026-09-08T08:17:20Z" 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=Normal1207machine # [ 35.946242] k3s[852]: I0908 08:17:20.809753 852 serving.go:392] Generated self-signed cert in-memory1208machine # [ 35.951414] k3s[852]: time="2026-09-08T08:17:20Z" 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=Normal1209machine # [ 36.043587] k3s[852]: I0908 08:17:20.908059 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="replicasets.apps"1210machine # [ 36.048454] k3s[852]: I0908 08:17:20.910567 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="statefulsets.apps"1211machine # [ 36.050635] k3s[852]: I0908 08:17:20.910686 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmchartconfigs.helm.cattle.io"1212machine # [ 36.053335] k3s[852]: I0908 08:17:20.910736 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="podtemplates"1213machine # [ 36.056522] k3s[852]: I0908 08:17:20.910804 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="controllerrevisions.apps"1214machine # [ 36.059663] k3s[852]: I0908 08:17:20.910823 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="cronjobs.batch"1215machine # [ 36.063816] k3s[852]: I0908 08:17:20.910871 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="networkpolicies.networking.k8s.io"1216machine # [ 36.067412] k3s[852]: I0908 08:17:20.910897 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="ingresses.networking.k8s.io"1217machine # [ 36.070582] k3s[852]: I0908 08:17:20.910919 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmcharts.helm.cattle.io"1218machine # [ 36.073681] k3s[852]: I0908 08:17:20.910935 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpoints"1219machine # [ 36.076654] k3s[852]: I0908 08:17:20.910953 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpointslices.discovery.k8s.io"1220machine # [ 36.079802] k3s[852]: I0908 08:17:20.910983 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="serviceaccounts"1221machine # [ 36.083007] k3s[852]: I0908 08:17:20.911000 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="daemonsets.apps"1222machine # [ 36.088892] k3s[852]: I0908 08:17:20.911039 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="rolebindings.rbac.authorization.k8s.io"1223machine # [ 36.091433] k3s[852]: I0908 08:17:20.911060 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="roles.rbac.authorization.k8s.io"1224machine # [ 36.097997] k3s[852]: I0908 08:17:20.911083 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="addons.k3s.cattle.io"1225machine # [ 36.105906] k3s[852]: I0908 08:17:20.911103 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="deployments.apps"1226machine # [ 36.109527] k3s[852]: I0908 08:17:20.911168 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="horizontalpodautoscalers.autoscaling"1227machine # [ 36.117235] k3s[852]: I0908 08:17:20.911189 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="jobs.batch"1228machine # [ 36.121004] k3s[852]: I0908 08:17:20.911213 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="poddisruptionbudgets.policy"1229machine # [ 36.123250] k3s[852]: I0908 08:17:20.911236 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="leases.coordination.k8s.io"1230machine # [ 36.132256] k3s[852]: I0908 08:17:20.911257 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="limitranges"1231machine # [ 36.134329] k3s[852]: I0908 08:17:20.911308 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="csistoragecapacities.storage.k8s.io"1232machine # [ 36.141090] k3s[852]: I0908 08:17:20.911335 852 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="resourceclaimtemplates.resource.k8s.io"1233machine # [ 36.146829] k3s[852]: I0908 08:17:20.944035 852 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller" requiredFeatureGates=["ClusterTrustBundle"]1234machine # [ 36.153173] k3s[852]: I0908 08:17:20.944096 852 controllermanager.go:579] "Warning: skipping controller" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller"1235machine # [ 36.155253] k3s[852]: I0908 08:17:20.944114 852 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="device-taint-eviction-controller" requiredFeatureGates=["DynamicResourceAllocation","DRADeviceTaints"]1236machine # [ 36.164105] k3s[852]: I0908 08:17:20.944122 852 controllermanager.go:579] "Warning: skipping controller" controller="device-taint-eviction-controller"1237machine # [ 36.249188] k3s[852]: time="2026-09-08T08:17:21Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1238machine # [ 36.250971] k3s[852]: I0908 08:17:21.071517 852 serving.go:392] Generated self-signed cert in-memory1239machine # [ 36.255271] k3s[852]: I0908 08:17:21.104596 852 replica_set.go:241] "Starting controller" name="replicaset"1240machine # [ 36.258909] k3s[852]: I0908 08:17:21.104684 852 shared_informer.go:370] "Waiting for caches to sync"1241machine # [ 36.262228] k3s[852]: I0908 08:17:21.105804 852 shared_informer.go:370] "Waiting for caches to sync"1242machine # [ 36.263596] k3s[852]: I0908 08:17:21.105880 852 tokencleaner.go:117] "Starting token cleaner controller"1243machine # [ 36.266686] k3s[852]: I0908 08:17:21.105897 852 shared_informer.go:370] "Waiting for caches to sync"1244machine # [ 36.268355] k3s[852]: I0908 08:17:21.106038 852 node_ipam_controller.go:142] "Starting ipam controller"1245machine # [ 36.269619] k3s[852]: I0908 08:17:21.106057 852 shared_informer.go:370] "Waiting for caches to sync"1246machine # [ 36.270846] k3s[852]: I0908 08:17:21.106092 852 vac_protection_controller.go:206] "Starting VAC protection controller"1247machine # [ 36.272657] k3s[852]: I0908 08:17:21.106107 852 shared_informer.go:370] "Waiting for caches to sync"1248machine # [ 36.274057] k3s[852]: I0908 08:17:21.106187 852 controller.go:423] "Starting resource claim controller"1249machine # [ 36.275427] k3s[852]: I0908 08:17:21.106198 852 shared_informer.go:370] "Waiting for caches to sync"1250machine # [ 36.277031] k3s[852]: I0908 08:17:21.106280 852 pv_controller_base.go:307] "Starting persistent volume controller"1251machine # [ 36.282460] k3s[852]: I0908 08:17:21.106343 852 shared_informer.go:370] "Waiting for caches to sync"1252machine # [ 36.283801] k3s[852]: I0908 08:17:21.106382 852 pvc_protection_controller.go:166] "Starting PVC protection controller"1253machine # [ 36.287143] k3s[852]: I0908 08:17:21.106394 852 shared_informer.go:370] "Waiting for caches to sync"1254machine # [ 36.289615] k3s[852]: I0908 08:17:21.106480 852 endpoints_controller.go:193] "Starting endpoint controller"1255machine # [ 36.290908] k3s[852]: I0908 08:17:21.106510 852 shared_informer.go:370] "Waiting for caches to sync"1256machine # [ 36.293187] k3s[852]: I0908 08:17:21.106902 852 deployment_controller.go:172] "Starting controller" controller="deployment"1257machine # [ 36.295098] k3s[852]: I0908 08:17:21.106927 852 shared_informer.go:370] "Waiting for caches to sync"1258machine # [ 36.296727] k3s[852]: I0908 08:17:21.106961 852 pv_protection_controller.go:81] "Starting PV protection controller"1259machine # [ 36.298498] k3s[852]: I0908 08:17:21.106975 852 shared_informer.go:370] "Waiting for caches to sync"1260machine # [ 36.299746] k3s[852]: I0908 08:17:21.107018 852 taint_eviction.go:283] "Starting" controller="taint-eviction-controller"1261machine # [ 36.303363] k3s[852]: I0908 08:17:21.107091 852 taint_eviction.go:288] "Sending events to API server"1262machine # [ 36.305709] k3s[852]: I0908 08:17:21.107100 852 shared_informer.go:370] "Waiting for caches to sync"1263machine # [ 36.306945] k3s[852]: I0908 08:17:21.107141 852 gc_controller.go:98] "Starting GC controller"1264machine # [ 36.310025] k3s[852]: I0908 08:17:21.107152 852 shared_informer.go:370] "Waiting for caches to sync"1265machine # [ 36.312846] k3s[852]: I0908 08:17:21.107209 852 disruption.go:458] "Sending events to api server."1266machine # [ 36.315269] k3s[852]: I0908 08:17:21.107254 852 disruption.go:465] "Starting disruption controller"1267machine # [ 36.316590] k3s[852]: I0908 08:17:21.107263 852 shared_informer.go:370] "Waiting for caches to sync"1268machine # [ 36.317838] k3s[852]: I0908 08:17:21.107327 852 node_lifecycle_controller.go:453] "Sending events to api server"1269machine # [ 36.319178] k3s[852]: I0908 08:17:21.107363 852 node_lifecycle_controller.go:460] "Starting node controller"1270machine # [ 36.324269] k3s[852]: I0908 08:17:21.107373 852 shared_informer.go:370] "Waiting for caches to sync"1271machine # [ 36.325571] k3s[852]: I0908 08:17:21.107464 852 servicecidrs_controller.go:136] "Starting" controller="service-cidr-controller"1272machine # [ 36.327049] k3s[852]: I0908 08:17:21.107479 852 shared_informer.go:370] "Waiting for caches to sync"1273machine # [ 36.332188] k3s[852]: I0908 08:17:21.107512 852 namespace_controller.go:202] "Starting namespace controller"1274machine # [ 36.333616] k3s[852]: I0908 08:17:21.107522 852 shared_informer.go:370] "Waiting for caches to sync"1275machine # [ 36.334842] k3s[852]: I0908 08:17:21.107571 852 horizontal.go:204] "Starting HPA controller"1276machine # [ 36.339017] k3s[852]: I0908 08:17:21.107593 852 shared_informer.go:370] "Waiting for caches to sync"1277machine # [ 36.341611] k3s[852]: I0908 08:17:21.107631 852 cleaner.go:83] "Starting CSR cleaner controller"1278machine # [ 36.342922] k3s[852]: I0908 08:17:21.107774 852 stateful_set.go:180] "Starting stateful set controller"1279machine # [ 36.345745] k3s[852]: I0908 08:17:21.107806 852 shared_informer.go:370] "Waiting for caches to sync"1280machine # [ 36.347018] k3s[852]: I0908 08:17:21.107896 852 cronjob_controllerv2.go:143] "Starting cronjob controller v2"1281machine # [ 36.351406] k3s[852]: I0908 08:17:21.107914 852 shared_informer.go:370] "Waiting for caches to sync"1282machine # [ 36.353717] k3s[852]: I0908 08:17:21.107947 852 ttl_controller.go:127] "Starting TTL controller"1283machine # [ 36.354954] k3s[852]: I0908 08:17:21.107970 852 shared_informer.go:370] "Waiting for caches to sync"1284machine # [ 36.357587] k3s[852]: I0908 08:17:21.108011 852 expand_controller.go:328] "Starting expand controller"1285machine # [ 36.359956] k3s[852]: I0908 08:17:21.108027 852 shared_informer.go:370] "Waiting for caches to sync"1286machine # [ 36.365417] k3s[852]: I0908 08:17:21.108047 852 clusterroleaggregation_controller.go:194] "Starting ClusterRoleAggregator controller"1287machine # [ 36.367176] k3s[852]: I0908 08:17:21.108059 852 shared_informer.go:370] "Waiting for caches to sync"1288machine # [ 36.368482] k3s[852]: I0908 08:17:21.108081 852 controller.go:174] "Starting ephemeral volume controller"1289machine # [ 36.369747] k3s[852]: I0908 08:17:21.108094 852 shared_informer.go:370] "Waiting for caches to sync"1290machine # [ 36.370956] k3s[852]: I0908 08:17:21.108132 852 legacy_serviceaccount_token_cleaner.go:103] "Starting legacy service account token cleaner controller"1291machine # Error from server (NotFound): namespaces "niks3" not found1292machine # [ 36.380230] k3s[852]: I0908 08:17:21.108152 852 shared_informer.go:370] "Waiting for caches to sync"1293machine # [ 36.381548] k3s[852]: I0908 08:17:21.108256 852 endpointslice_controller.go:283] "Starting endpoint slice controller"1294machine # [ 36.382959] k3s[852]: I0908 08:17:21.108270 852 shared_informer.go:370] "Waiting for caches to sync"1295machine # [ 36.390256] k3s[852]: I0908 08:17:21.108378 852 replica_set.go:241] "Starting controller" name="replicationcontroller"1296machine # [ 36.391797] k3s[852]: I0908 08:17:21.108405 852 shared_informer.go:370] "Waiting for caches to sync"1297machine # [ 36.394681] k3s[852]: I0908 08:17:21.108492 852 daemon_controller.go:309] "Starting daemon sets controller"1298machine # [ 36.397664] k3s[852]: I0908 08:17:21.108507 852 shared_informer.go:370] "Waiting for caches to sync"1299machine # [ 36.398920] k3s[852]: I0908 08:17:21.108528 852 certificate_controller.go:120] "Starting certificate controller" name="csrapproving"1300machine # [ 36.403441] k3s[852]: I0908 08:17:21.108549 852 shared_informer.go:370] "Waiting for caches to sync"1301machine # [ 36.404943] k3s[852]: I0908 08:17:21.108659 852 attach_detach_controller.go:335] "Starting attach detach controller"1302machine # [ 36.407988] k3s[852]: I0908 08:17:21.108673 852 shared_informer.go:370] "Waiting for caches to sync"1303machine # [ 36.409294] k3s[852]: I0908 08:17:21.108693 852 ttlafterfinished_controller.go:112] "Starting TTL after finished controller"1304machine # [ 36.410761] k3s[852]: I0908 08:17:21.108704 852 shared_informer.go:370] "Waiting for caches to sync"1305machine # [ 36.412874] k3s[852]: I0908 08:17:21.108723 852 publisher.go:107] "Starting root CA cert publisher controller"1306machine # [ 36.414208] k3s[852]: I0908 08:17:21.108736 852 shared_informer.go:370] "Waiting for caches to sync"1307machine # [ 36.415558] k3s[852]: I0908 08:17:21.108807 852 endpointslicemirroring_controller.go:226] "Starting EndpointSliceMirroring controller"1308machine # [ 36.417281] k3s[852]: I0908 08:17:21.108829 852 shared_informer.go:370] "Waiting for caches to sync"1309machine # [ 36.418481] k3s[852]: I0908 08:17:21.109110 852 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-legacy-unknown"1310machine # [ 36.420265] k3s[852]: I0908 08:17:21.109123 852 shared_informer.go:370] "Waiting for caches to sync"1311machine # [ 36.422142] k3s[852]: I0908 08:17:21.109142 852 shared_informer.go:370] "Waiting for caches to sync"1312machine # [ 36.423348] k3s[852]: I0908 08:17:21.109178 852 serviceaccounts_controller.go:117] "Starting service account controller"1313machine # [ 36.424840] k3s[852]: I0908 08:17:21.109190 852 shared_informer.go:370] "Waiting for caches to sync"1314machine # [ 36.426447] k3s[852]: I0908 08:17:21.109268 852 job_controller.go:254] "Starting job controller"1315machine # [ 36.428130] k3s[852]: I0908 08:17:21.109281 852 shared_informer.go:370] "Waiting for caches to sync"1316machine # [ 36.429435] k3s[852]: I0908 08:17:21.136736 852 garbagecollector.go:141] "Starting controller" controller="garbagecollector"1317machine # [ 36.431616] k3s[852]: I0908 08:17:21.136801 852 shared_informer.go:370] "Waiting for caches to sync"1318machine # [ 36.434941] k3s[852]: I0908 08:17:21.136909 852 resource_quota_controller.go:297] "Starting resource quota controller"1319machine # [ 36.436955] k3s[852]: I0908 08:17:21.136931 852 shared_informer.go:370] "Waiting for caches to sync"1320machine # [ 36.438524] k3s[852]: I0908 08:17:21.137290 852 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-client"1321machine # [ 36.443777] k3s[852]: I0908 08:17:21.137307 852 shared_informer.go:370] "Waiting for caches to sync"1322machine # [ 36.446117] k3s[852]: I0908 08:17:21.137325 852 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kube-apiserver-client"1323machine # [ 36.448673] k3s[852]: I0908 08:17:21.137340 852 shared_informer.go:370] "Waiting for caches to sync"1324machine # [ 36.449883] k3s[852]: I0908 08:17:21.137392 852 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"1325machine # [ 36.452462] k3s[852]: I0908 08:17:21.157293 852 graph_builder.go:386] "Running" component="GraphBuilder"1326machine # [ 36.453709] k3s[852]: I0908 08:17:21.157345 852 resource_quota_monitor.go:309] "QuotaMonitor running"1327machine # [ 36.454937] k3s[852]: I0908 08:17:21.157533 852 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"1328machine # [ 36.457569] k3s[852]: I0908 08:17:21.157708 852 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-serving"1329machine # [ 36.459244] k3s[852]: I0908 08:17:21.157724 852 shared_informer.go:370] "Waiting for caches to sync"1330machine # [ 36.460523] k3s[852]: I0908 08:17:21.157779 852 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"1331machine # [ 36.463028] k3s[852]: I0908 08:17:21.157870 852 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"1332machine # [ 36.465615] k3s[852]: I0908 08:17:21.178824 852 shared_informer.go:370] "Waiting for caches to sync"1333machine # [ 36.466803] k3s[852]: I0908 08:17:21.251833 852 shared_informer.go:370] "Waiting for caches to sync"1334machine # [ 36.468081] k3s[852]: I0908 08:17:21.320871 852 shared_informer.go:377] "Caches are synced"1335machine # [ 36.572820] k3s[852]: I0908 08:17:21.437249 852 controllermanager.go:160] Version: v1.35.8+k3s11336machine # [ 36.576567] k3s[852]: I0908 08:17:21.440798 852 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1337machine # [ 36.579612] k3s[852]: I0908 08:17:21.440866 852 shared_informer.go:370] "Waiting for caches to sync"1338machine # [ 36.581855] k3s[852]: I0908 08:17:21.440920 852 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1339machine # [ 36.587978] k3s[852]: I0908 08:17:21.440941 852 shared_informer.go:370] "Waiting for caches to sync"1340machine # [ 36.589500] k3s[852]: I0908 08:17:21.440954 852 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1341machine # [ 36.591995] k3s[852]: I0908 08:17:21.440982 852 shared_informer.go:370] "Waiting for caches to sync"1342machine # [ 36.593503] k3s[852]: I0908 08:17:21.441273 852 secure_serving.go:211] Serving securely on 127.0.0.1:102581343machine # [ 36.594885] k3s[852]: I0908 08:17:21.442092 852 tlsconfig.go:243] "Starting DynamicServingCertificateController"1344machine # [ 36.596465] k3s[852]: time="2026-09-08T08:17:21Z" level=info msg="Creating service-lb-controller event broadcaster"1345machine # [ 36.630372] k3s[852]: I0908 08:17:21.494459 852 controller.go:667] quota admission added evaluator for: deployments.apps1346machine # [ 36.641395] k3s[852]: I0908 08:17:21.505898 852 shared_informer.go:377] "Caches are synced"1347machine # [ 36.643815] k3s[852]: I0908 08:17:21.507496 852 shared_informer.go:377] "Caches are synced"1348machine # [ 36.646222] k3s[852]: I0908 08:17:21.507583 852 shared_informer.go:377] "Caches are synced"1349machine # [ 36.647404] k3s[852]: I0908 08:17:21.507680 852 shared_informer.go:377] "Caches are synced"1350machine # [ 36.651469] k3s[852]: I0908 08:17:21.507970 852 shared_informer.go:377] "Caches are synced"1351machine # [ 36.652870] k3s[852]: I0908 08:17:21.508006 852 shared_informer.go:377] "Caches are synced"1352machine # [ 36.654948] k3s[852]: I0908 08:17:21.508063 852 shared_informer.go:377] "Caches are synced"1353machine # [ 36.657226] k3s[852]: I0908 08:17:21.508099 852 shared_informer.go:377] "Caches are synced"1354machine # [ 36.659345] k3s[852]: I0908 08:17:21.508139 852 shared_informer.go:377] "Caches are synced"1355machine # [ 36.662236] k3s[852]: I0908 08:17:21.508180 852 shared_informer.go:377] "Caches are synced"1356machine # [ 36.663487] k3s[852]: I0908 08:17:21.510201 852 shared_informer.go:377] "Caches are synced"1357machine # [ 36.665994] k3s[852]: I0908 08:17:21.510273 852 shared_informer.go:377] "Caches are synced"1358machine # [ 36.668171] k3s[852]: I0908 08:17:21.510395 852 range_allocator.go:177] "Sending events to api server"1359machine # [ 36.669446] k3s[852]: I0908 08:17:21.510450 852 range_allocator.go:181] "Starting range CIDR allocator"1360machine # [ 36.670707] k3s[852]: I0908 08:17:21.510459 852 shared_informer.go:370] "Waiting for caches to sync"1361machine # [ 36.675240] k3s[852]: I0908 08:17:21.510466 852 shared_informer.go:377] "Caches are synced"1362machine # [ 36.676753] k3s[852]: I0908 08:17:21.510597 852 shared_informer.go:377] "Caches are synced"1363machine # [ 36.677880] k3s[852]: I0908 08:17:21.513225 852 shared_informer.go:377] "Caches are synced"1364machine # [ 36.682385] k3s[852]: I0908 08:17:21.513432 852 shared_informer.go:377] "Caches are synced"1365machine # [ 36.683705] k3s[852]: I0908 08:17:21.513677 852 shared_informer.go:377] "Caches are synced"1366machine # [ 36.684914] k3s[852]: I0908 08:17:21.513776 852 shared_informer.go:377] "Caches are synced"1367machine # [ 36.686044] k3s[852]: I0908 08:17:21.513872 852 shared_informer.go:377] "Caches are synced"1368machine # [ 36.687174] k3s[852]: I0908 08:17:21.515321 852 shared_informer.go:377] "Caches are synced"1369machine # [ 36.692360] k3s[852]: I0908 08:17:21.515362 852 shared_informer.go:377] "Caches are synced"1370machine # [ 36.693522] k3s[852]: I0908 08:17:21.515425 852 shared_informer.go:377] "Caches are synced"1371machine # [ 36.694651] k3s[852]: I0908 08:17:21.515481 852 shared_informer.go:377] "Caches are synced"1372machine # [ 36.695790] k3s[852]: I0908 08:17:21.515579 852 shared_informer.go:377] "Caches are synced"1373machine # [ 36.698206] k3s[852]: I0908 08:17:21.521172 852 shared_informer.go:377] "Caches are synced"1374machine # [ 36.699395] k3s[852]: I0908 08:17:21.526196 852 shared_informer.go:377] "Caches are synced"1375machine # [ 36.702136] k3s[852]: I0908 08:17:21.526302 852 shared_informer.go:377] "Caches are synced"1376machine # [ 36.703373] k3s[852]: I0908 08:17:21.526337 852 shared_informer.go:377] "Caches are synced"1377machine # [ 36.706357] k3s[852]: I0908 08:17:21.526375 852 shared_informer.go:377] "Caches are synced"1378machine # [ 36.707591] k3s[852]: I0908 08:17:21.526406 852 shared_informer.go:377] "Caches are synced"1379machine # [ 36.712246] k3s[852]: I0908 08:17:21.526589 852 shared_informer.go:377] "Caches are synced"1380machine # [ 36.713636] k3s[852]: I0908 08:17:21.529374 852 shared_informer.go:377] "Caches are synced"1381machine # [ 36.714951] k3s[852]: I0908 08:17:21.529566 852 shared_informer.go:377] "Caches are synced"1382machine # [ 36.716215] k3s[852]: I0908 08:17:21.529607 852 shared_informer.go:377] "Caches are synced"1383machine # [ 36.717515] k3s[852]: I0908 08:17:21.529633 852 shared_informer.go:377] "Caches are synced"1384machine # [ 36.721454] k3s[852]: I0908 08:17:21.530079 852 shared_informer.go:377] "Caches are synced"1385machine # [ 36.722719] k3s[852]: I0908 08:17:21.530145 852 shared_informer.go:377] "Caches are synced"1386machine # [ 36.723874] k3s[852]: I0908 08:17:21.537120 852 shared_informer.go:377] "Caches are synced"1387machine # [ 36.728256] k3s[852]: I0908 08:17:21.537482 852 shared_informer.go:377] "Caches are synced"1388machine # [ 36.729520] k3s[852]: I0908 08:17:21.539331 852 shared_informer.go:377] "Caches are synced"1389machine # [ 36.730651] k3s[852]: I0908 08:17:21.542747 852 shared_informer.go:377] "Caches are synced"1390machine # [ 36.731809] k3s[852]: I0908 08:17:21.544388 852 shared_informer.go:377] "Caches are synced"1391machine # [ 36.733031] k3s[852]: I0908 08:17:21.544515 852 shared_informer.go:377] "Caches are synced"1392machine # [ 36.734143] k3s[852]: I0908 08:17:21.557941 852 shared_informer.go:377] "Caches are synced"1393machine # [ 36.735273] k3s[852]: I0908 08:17:21.571447 852 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161394machine # [ 36.740269] k3s[852]: I0908 08:17:21.574731 852 controller.go:667] quota admission added evaluator for: replicasets.apps1395machine # [ 36.741868] k3s[852]: I0908 08:17:21.584774 852 shared_informer.go:377] "Caches are synced"1396machine # [ 36.758697] k3s[852]: I0908 08:17:21.623176 852 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161397machine # [ 36.766904] k3s[852]: I0908 08:17:21.631159 852 alloc.go:329] "allocated clusterIPs" service="kube-system/kube-dns" clusterIPs={"IPv4":"10.43.0.10"}1398machine # [ 36.773219] k3s[852]: time="2026-09-08T08:17:21Z" 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=Normal1399machine # [ 36.939481] k3s[852]: time="2026-09-08T08:17:21Z" level=info msg="Starting /v1, Kind=Node controller"1400machine # [ 36.947539] k3s[852]: time="2026-09-08T08:17:21Z" level=info msg="Starting /v1, Kind=Pod controller"1401machine # [ 36.955587] k3s[852]: time="2026-09-08T08:17:21Z" level=info msg="Starting apps/v1, Kind=DaemonSet controller"1402machine # [ 36.963611] k3s[852]: time="2026-09-08T08:17:21Z" level=info msg="Starting discovery.k8s.io/v1, Kind=EndpointSlice controller"1403machine # [ 36.968374] k3s[852]: I0908 08:17:21.828288 852 controllermanager.go:329] Started "cloud-node-lifecycle-controller"1404machine # [ 36.969940] k3s[852]: I0908 08:17:21.828917 852 controllermanager.go:329] Started "service-lb-controller"1405machine # [ 36.971396] k3s[852]: W0908 08:17:21.828934 852 controllermanager.go:306] "node-route-controller" is disabled1406machine # [ 36.975222] k3s[852]: I0908 08:17:21.829695 852 controllermanager.go:329] Started "cloud-node-controller"1407machine # [ 36.976845] k3s[852]: I0908 08:17:21.830928 852 node_lifecycle_controller.go:112] Sending events to api server1408machine # [ 36.978586] k3s[852]: I0908 08:17:21.831035 852 node_controller.go:176] Sending events to api server.1409machine # [ 36.980600] k3s[852]: I0908 08:17:21.831193 852 controller.go:235] Starting service controller1410machine # [ 36.982288] k3s[852]: I0908 08:17:21.831216 852 shared_informer.go:370] "Waiting for caches to sync"1411machine # [ 36.983700] k3s[852]: I0908 08:17:21.831303 852 node_controller.go:185] Waiting for informer caches to sync1412machine # [ 37.140548] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported docker.io/rancher/klipper-helm:v0.13.3-build20260727"1413machine # [ 37.142995] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Tagged docker.io/rancher/klipper-helm@sha256:5425a2b4613d2458dbdff99218e8d487ebb59c20e7a941f061c0777070f0aac1"1414machine # [ 37.145507] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported docker.io/rancher/klipper-lb:v0.4.17"1415machine # [ 37.146965] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Tagged docker.io/rancher/klipper-lb@sha256:910944bb0bd94f060a82a56ca1ea1c577d3e49b3473a093a47a985f32e92d94a"1416machine # [ 37.149275] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported docker.io/rancher/local-path-provisioner:v0.0.37"1417machine # [ 37.151039] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Tagged docker.io/rancher/local-path-provisioner@sha256:e757967a5ec338f6a9b371c5a9688bedaa8c3578ea3dd4db329ea0084be0a86f"1418machine # [ 37.153705] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported docker.io/rancher/mirrored-coredns-coredns:1.14.6"1419machine # [ 37.155208] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Tagged docker.io/rancher/mirrored-coredns-coredns@sha256:900f9c109f7a33545d3c811516e8376df9019147b750f5ce3e254468769176ea"1420machine # [ 37.157906] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported docker.io/rancher/mirrored-library-busybox:1.37.0"1421machine # [ 37.159601] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Tagged docker.io/rancher/mirrored-library-busybox@sha256:101b4afd76732482eff9b95cae5f94bcf295e521fbec4e01b69c5421f3f3f3e5"1422machine # [ 37.162087] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported docker.io/rancher/mirrored-library-traefik:3.7.8"1423machine # [ 37.165281] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Tagged docker.io/rancher/mirrored-library-traefik@sha256:4299bbed850421258fc5448c2e0e6ad350981d4d335a68de11b92448aedbefe5"1424machine # [ 37.167738] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported docker.io/rancher/mirrored-metrics-server:v0.9.0"1425machine # [ 37.172150] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Tagged docker.io/rancher/mirrored-metrics-server@sha256:d9862115e7c7881280d3d75ca26bda8ffc0fc213315979575bf23ce9826205c0"1426machine # [ 37.174551] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported docker.io/rancher/mirrored-pause:3.10.2"1427machine # [ 37.178456] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Tagged docker.io/rancher/mirrored-pause@sha256:f548e0e8e3dc1896ca956272154dde3314e8cc4fde0a57577ee9fa1c63f5baf4"1428machine # [ 37.189672] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1429machine # [ 37.267093] k3s[852]: I0908 08:17:22.131493 852 shared_informer.go:377] "Caches are synced"1430machine # [ 37.590617] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Imported 8 images from /var/lib/rancher/k3s/agent/images/k3s-airgap-images-arm64.tar.zst in 9.67227242s"1431machine # [ 37.593793] k3s[852]: time="2026-09-08T08:17:22Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/niks3-server.tar"1432machine # Error from server (NotFound): namespaces "niks3" not found1433machine # [ 38.068083] k3s[852]: time="2026-09-08T08:17:22Z" 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::a63e:f22e:72a2:90f0 --node-labels= --read-only-port=0"1434machine # [ 38.075743] k3s[852]: 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.1435machine # [ 38.101342] k3s[852]: I0908 08:17:22.965786 852 server.go:521] "Kubelet version" kubeletVersion="v1.35.8+k3s1"1436machine # [ 38.104112] k3s[852]: I0908 08:17:22.965863 852 server.go:523] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1437machine # [ 38.106495] k3s[852]: I0908 08:17:22.965970 852 watchdog_linux.go:95] "Systemd watchdog is not enabled"1438machine # [ 38.108906] k3s[852]: I0908 08:17:22.965988 852 watchdog_linux.go:138] "Systemd watchdog is not enabled or the interval is invalid, so health checking will not be started."1439machine # [ 38.112254] k3s[852]: I0908 08:17:22.970101 852 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt"1440machine # [ 38.116392] k3s[852]: I0908 08:17:22.980921 852 server.go:1414] "Using cgroup driver setting received from the CRI runtime" cgroupDriver="systemd"1441machine # [ 38.122286] k3s[852]: I0908 08:17:22.986790 852 server.go:771] "--cgroups-per-qos enabled, but --cgroup-root was not specified. Defaulting to /"1442machine # [ 38.124932] k3s[852]: I0908 08:17:22.986843 852 server.go:832] "NoSwap is set due to memorySwapBehavior not specified" memorySwapBehavior="" FailSwapOn=false1443machine # [ 38.127200] k3s[852]: I0908 08:17:22.987210 852 container_manager_linux.go:272] "Container manager verified user specified cgroup-root exists" cgroupRoot=[]1444machine # [ 38.129626] k3s[852]: I0908 08:17:22.987240 852 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}1445machine # [ 38.146611] k3s[852]: I0908 08:17:22.987553 852 topology_manager.go:143] "Creating topology manager with none policy"1446machine # [ 38.148476] k3s[852]: I0908 08:17:22.987576 852 container_manager_linux.go:308] "Creating device plugin manager"1447machine # [ 38.150190] k3s[852]: I0908 08:17:22.987706 852 container_manager_linux.go:317] "Creating Dynamic Resource Allocation (DRA) manager"1448machine # [ 38.152048] k3s[852]: I0908 08:17:22.993392 852 state_mem.go:41] "Initialized" logger="CPUManager state memory"1449machine # [ 38.153749] k3s[852]: I0908 08:17:22.993675 852 kubelet.go:482] "Attempting to sync node with API server"1450machine # [ 38.155178] k3s[852]: I0908 08:17:22.993704 852 kubelet.go:383] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests"1451machine # [ 38.157267] k3s[852]: I0908 08:17:22.993755 852 kubelet.go:394] "Adding apiserver pod source"1452machine # [ 38.158811] k3s[852]: I0908 08:17:22.993784 852 apiserver.go:42] "Waiting for node sync before watching apiserver pods"1453machine # [ 38.160787] k3s[852]: I0908 08:17:23.000446 852 kuberuntime_manager.go:304] "Container runtime initialized" containerRuntime="containerd" version="2.2.7-k3s1" apiVersion="v1"1454machine # [ 38.163187] k3s[852]: I0908 08:17:23.001618 852 kubelet.go:945] "Not starting ClusterTrustBundle informer because we are in static kubelet mode or the ClusterTrustBundleProjection featuregate is disabled"1455machine # [ 38.166061] k3s[852]: I0908 08:17:23.001653 852 kubelet.go:972] "Not starting PodCertificateRequest manager because we are in static kubelet mode or the PodCertificateProjection feature gate is disabled"1456machine # [ 38.176318] k3s[852]: I0908 08:17:23.010813 852 server.go:1252] "Started kubelet"1457machine # [ 38.179071] k3s[852]: I0908 08:17:23.013277 852 server.go:182] "Starting to listen" address="0.0.0.0" port=102501458machine # [ 38.181340] k3s[852]: I0908 08:17:23.017674 852 ratelimit.go:56] "Setting rate limiting for endpoint" service="podresources" qps=100 burstTokens=101459machine # [ 38.185881] k3s[852]: I0908 08:17:23.017817 852 server_v1.go:49] "podresources" method="list" useActivePods=true1460machine # [ 38.188290] k3s[852]: I0908 08:17:23.018175 852 server.go:254] "Starting to serve the podresources API" endpoint="unix:/var/lib/kubelet/pod-resources/kubelet.sock"1461machine # [ 38.190702] k3s[852]: I0908 08:17:23.019890 852 fs_resource_analyzer.go:69] "Starting FS ResourceAnalyzer"1462machine # [ 38.192823] k3s[852]: I0908 08:17:23.020436 852 server.go:317] "Adding debug handlers to kubelet server"1463machine # [ 38.194410] k3s[852]: I0908 08:17:23.025694 852 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"1464machine # [ 38.197619] k3s[852]: I0908 08:17:23.026708 852 volume_manager.go:311] "Starting Kubelet Volume Manager"1465machine # [ 38.201999] k3s[852]: E0908 08:17:23.027035 852 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found"1466machine # [ 38.204577] k3s[852]: I0908 08:17:23.031816 852 desired_state_of_world_populator.go:146] "Desired state populator starts to run"1467machine # [ 38.208589] k3s[852]: I0908 08:17:23.031968 852 reconciler.go:29] "Reconciler: start to sync state"1468machine # [ 38.209936] k3s[852]: I0908 08:17:23.050061 852 factory.go:223] Registration of the systemd container factory successfully1469machine # [ 38.211653] k3s[852]: I0908 08:17:23.050308 852 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 directory1470machine # [ 38.215924] k3s[852]: I0908 08:17:23.057520 852 shared_informer.go:377] "Caches are synced"1471machine # [ 38.217538] k3s[852]: E0908 08:17:23.060141 852 kubelet.go:1661] "Image garbage collection failed once. Stats initialization may not have completed yet" err="invalid capacity 0 on image filesystem"1472machine # [ 38.220274] k3s[852]: I0908 08:17:23.070845 852 factory.go:223] Registration of the containerd container factory successfully1473machine # [ 38.221933] k3s[852]: time="2026-09-08T08:17:23Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1474machine # [ 38.228084] k3s[852]: E0908 08:17:23.091584 852 nodelease.go:50] "Failed to get node when trying to set owner ref to the node lease" err="nodes \"machine\" not found" node="machine"1475machine # [ 38.246383] k3s[852]: I0908 08:17:23.110896 852 cpu_manager.go:225] "Starting" policy="none"1476machine # [ 38.249476] k3s[852]: I0908 08:17:23.110928 852 cpu_manager.go:226] "Reconciling" reconcilePeriod="10s"1477machine # [ 38.252334] k3s[852]: I0908 08:17:23.111015 852 state_mem.go:41] "Initialized" logger="CPUManager state checkpoint.CPUManager state memory"1478machine # [ 38.254009] k3s[852]: I0908 08:17:23.114297 852 policy_none.go:50] "Start"1479machine # [ 38.255128] k3s[852]: I0908 08:17:23.114342 852 memory_manager.go:187] "Starting memorymanager" policy="None"1480machine # [ 38.258053] k3s[852]: I0908 08:17:23.114404 852 state_mem.go:36] "Initializing new in-memory state store" logger="Memory Manager state checkpoint"1481machine # [ 38.264120] k3s[852]: I0908 08:17:23.127124 852 policy_none.go:44] "Start"1482machine # [ 38.265189] k3s[852]: E0908 08:17:23.128542 852 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found"1483machine # [ 38.272498] k3s[852]: I0908 08:17:23.137002 852 shared_informer.go:377] "Caches are synced"1484machine # [ 38.274765] k3s[852]: I0908 08:17:23.139155 852 garbagecollector.go:166] "Garbage collector: all resource monitors have synced"1485machine # [ 38.277657] k3s[852]: I0908 08:17:23.140251 852 garbagecollector.go:169] "Proceeding to collect garbage"1486machine # [ 38.289542] systemd[1]: Created slice libcontainer container kubepods.slice.1487machine # [ 38.325483] systemd[1]: Created slice libcontainer container kubepods-burstable.slice.1488machine # [ 38.337261] systemd[1]: Created slice libcontainer container kubepods-besteffort.slice.1489machine # [ 38.359331] k3s[852]: E0908 08:17:23.223840 852 manager.go:525] "Failed to read data from checkpoint" err="checkpoint is not found" checkpoint="kubelet_internal_checkpoint"1490machine # [ 38.363357] k3s[852]: I0908 08:17:23.224270 852 eviction_manager.go:194] "Eviction manager: starting control loop"1491machine # [ 38.366081] k3s[852]: I0908 08:17:23.224303 852 container_log_manager.go:146] "Initializing container log rotate workers" workers=1 monitorPeriod="10s"1492machine # [ 38.372590] k3s[852]: I0908 08:17:23.237061 852 plugin_manager.go:121] "Starting Kubelet Plugin Manager"1493machine # [ 38.374214] k3s[852]: E0908 08:17:23.237834 852 eviction_manager.go:272] "eviction manager: failed to check if we have separate container filesystem. Ignoring." err="no imagefs label for configured runtime"1494machine # [ 38.379011] k3s[852]: E0908 08:17:23.237935 852 eviction_manager.go:297] "Eviction manager: failed to get summary stats" err="failed to get node info: node \"machine\" not found"1495machine # [ 38.463531] k3s[852]: I0908 08:17:23.327865 852 kubelet_node_status.go:74] "Attempting to register node" node="machine"1496machine # [ 38.479977] k3s[852]: I0908 08:17:23.341239 852 kubelet_node_status.go:77] "Successfully registered node" node="machine"1497machine # [ 38.484226] k3s[852]: E0908 08:17:23.341296 852 kubelet_node_status.go:474] "Error updating node status, will retry" err="error getting node \"machine\": node \"machine\" not found"1498machine # [ 38.500712] k3s[852]: I0908 08:17:23.365200 852 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"1499machine # [ 38.510007] k3s[852]: time="2026-09-08T08:17:23Z" level=info msg="Adding node OwnerReference to node-password secret machine.node-password.k3s"1500machine # [ 38.512518] k3s[852]: I0908 08:17:23.366832 852 node_controller.go:429] Initializing node machine with cloud provider1501machine # [ 38.516583] k3s[852]: I0908 08:17:23.381098 852 node_controller.go:233] error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing1502machine # [ 38.520111] k3s[852]: E0908 08:17:23.383530 852 node_controller.go:244] "Unhandled Error" err="error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing" logger="UnhandledError"1503machine # [ 38.537132] k3s[852]: I0908 08:17:23.401566 852 node_controller.go:429] Initializing node machine with cloud provider1504machine # [ 38.538892] k3s[852]: I0908 08:17:23.401652 852 node_controller.go:233] error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing1505machine # [ 38.545471] k3s[852]: E0908 08:17:23.401682 852 node_controller.go:244] "Unhandled Error" err="error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing" logger="UnhandledError"1506machine # [ 38.549274] k3s[852]: I0908 08:17:23.413667 852 node_controller.go:429] Initializing node machine with cloud provider1507machine # [ 38.560532] k3s[852]: I0908 08:17:23.424940 852 node_controller.go:233] error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing1508machine # [ 38.563411] k3s[852]: E0908 08:17:23.425010 852 node_controller.go:244] "Unhandled Error" err="error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing" logger="UnhandledError"1509machine # [ 38.568351] k3s[852]: I0908 08:17:23.424715 852 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv4"1510machine # [ 38.591386] k3s[852]: I0908 08:17:23.455762 852 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv6"1511machine # [ 38.596337] k3s[852]: I0908 08:17:23.458019 852 status_manager.go:249] "Starting to sync pod status with apiserver"1512machine # [ 38.599199] k3s[852]: I0908 08:17:23.458114 852 kubelet.go:2506] "Starting kubelet main sync loop"1513machine # [ 38.602938] k3s[852]: E0908 08:17:23.458237 852 kubelet.go:2530] "Skipping pod synchronization" err="PLEG is not healthy: pleg has yet to be successful"1514machine # [ 38.609044] k3s[852]: I0908 08:17:23.456272 852 node_controller.go:429] Initializing node machine with cloud provider1515machine # [ 38.611349] k3s[852]: I0908 08:17:23.472384 852 node_controller.go:233] error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing1516machine # [ 38.614076] k3s[852]: E0908 08:17:23.472438 852 node_controller.go:244] "Unhandled Error" err="error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing" logger="UnhandledError"1517machine # [ 38.618450] k3s[852]: I0908 08:17:23.472510 852 node_controller.go:429] Initializing node machine with cloud provider1518machine # [ 38.637197] k3s[852]: time="2026-09-08T08:17:23Z" level=info msg="Annotations and labels have been set successfully on node: machine"1519machine # [ 38.652836] k3s[852]: I0908 08:17:23.517302 852 range_allocator.go:433] "Set node PodCIDR" node="machine" podCIDRs=["10.42.0.0/24"]1520machine # [ 38.654771] k3s[852]: time="2026-09-08T08:17:23Z" level=info msg="Starting flannel with backend vxlan"1521machine # [ 38.659075] k3s[852]: time="2026-09-08T08:17:23Z" level=info msg="Synced coredns NodeHosts entries for machine"1522machine # [ 38.664758] k3s[852]: I0908 08:17:23.525402 852 kuberuntime_manager.go:2095] "Updating runtime config through cri with podcidr" CIDR="10.42.0.0/24"1523machine # [ 38.678885] k3s[852]: I0908 08:17:23.543331 852 kubelet_network.go:47] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="10.42.0.0/24"1524machine # [ 38.701934] k3s[852]: I0908 08:17:23.566354 852 kubelet_node_status.go:427] "Fast updating node status as it just became ready"1525machine # [ 38.772377] k3s[852]: I0908 08:17:23.636480 852 topologycache.go:237] "Can't get CPU or zone information for node" node="machine"1526machine # [ 38.798428] k3s[852]: E0908 08:17:23.662881 852 range_allocator.go:438] "Failed to update node PodCIDR after multiple attempts" err="failed to patch node CIDR: Node \"machine\" is invalid: [spec.podCIDRs: Invalid value: [\"10.42.1.0/24\",\"10.42.0.0/24\"]: may specify no more than one CIDR for each IP family, spec.podCIDRs: Forbidden: node updates may not change podCIDR except from \"\" to valid]" node="machine" podCIDRs=["10.42.1.0/24"]1527machine # [ 38.806692] k3s[852]: E0908 08:17:23.668297 852 range_allocator.go:444] "CIDR assignment for node failed. Releasing allocated CIDR" err="failed to patch node CIDR: Node \"machine\" is invalid: [spec.podCIDRs: Invalid value: [\"10.42.1.0/24\",\"10.42.0.0/24\"]: may specify no more than one CIDR for each IP family, spec.podCIDRs: Forbidden: node updates may not change podCIDR except from \"\" to valid]" node="machine"1528machine # [ 38.817629] k3s[852]: E0908 08:17:23.668499 852 range_allocator.go:257] "Error processing node work item" err="error syncing 'machine': failed to patch node CIDR: Node \"machine\" is invalid: [spec.podCIDRs: Invalid value: [\"10.42.1.0/24\",\"10.42.0.0/24\"]: may specify no more than one CIDR for each IP family, spec.podCIDRs: Forbidden: node updates may not change podCIDR except from \"\" to valid], requeuing" logger="UnhandledError"1529machine # [ 38.827984] k3s[852]: time="2026-09-08T08:17:23Z" 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=Normal1530machine # [ 38.960247] k3s[852]: I0908 08:17:23.822275 852 node_controller.go:474] Successfully initialized node machine with cloud provider1531machine # [ 38.962000] k3s[852]: I0908 08:17:23.823418 852 event.go:389] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="v1" type="Normal" reason="Synced" message="Node synced successfully"1532machine # [ 38.972459] k3s[852]: time="2026-09-08T08:17:23Z" 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=Normal1533machine # [ 38.990687] k3s[852]: I0908 08:17:23.853986 852 server.go:173] "Starting Kubernetes Scheduler" version="v1.35.8+k3s1"1534machine # [ 38.993817] k3s[852]: I0908 08:17:23.854048 852 server.go:175] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1535machine # [ 39.014416] k3s[852]: I0908 08:17:23.878885 852 secure_serving.go:211] Serving securely on 127.0.0.1:102591536machine # [ 39.017062] k3s[852]: I0908 08:17:23.879346 852 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1537machine # [ 39.019272] k3s[852]: I0908 08:17:23.879385 852 shared_informer.go:370] "Waiting for caches to sync"1538machine # [ 39.021804] k3s[852]: I0908 08:17:23.879454 852 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"1539machine # [ 39.028215] k3s[852]: I0908 08:17:23.879733 852 tlsconfig.go:243] "Starting DynamicServingCertificateController"1540machine # [ 39.029705] k3s[852]: I0908 08:17:23.883323 852 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1541machine # [ 39.031822] k3s[852]: I0908 08:17:23.883365 852 shared_informer.go:370] "Waiting for caches to sync"1542machine # [ 39.033228] k3s[852]: I0908 08:17:23.883405 852 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1543machine # [ 39.038470] k3s[852]: I0908 08:17:23.883422 852 shared_informer.go:370] "Waiting for caches to sync"1544machine # [ 39.143654] k3s[852]: I0908 08:17:24.006385 852 apiserver.go:52] "Watching apiserver"1545machine # [ 39.221997] k3s[852]: I0908 08:17:24.085124 852 controller.go:667] quota admission added evaluator for: helmcharts.helm.cattle.io1546machine # [ 39.255610] k3s[852]: time="2026-09-08T08:17:24Z" level=info msg="Labels and annotations have been set successfully on node: machine"1547machine # [ 39.257625] k3s[852]: time="2026-09-08T08:17:24Z" 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=Normal1548machine # [ 39.267537] k3s[852]: I0908 08:17:24.131937 852 desired_state_of_world_populator.go:154] "Finished populating initial desired state of world"1549machine # [ 39.275595] k3s[852]: I0908 08:17:24.139959 852 server.go:218] "Successfully retrieved NodeIPs" NodeIPs=["10.0.2.15","fec0::a63e:f22e:72a2:90f0"]1550machine # [ 39.278367] k3s[852]: E0908 08:17:24.142834 852 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`"1551machine # [ 39.315136] k3s[852]: I0908 08:17:24.179501 852 shared_informer.go:377] "Caches are synced"1552machine # [ 39.319070] k3s[852]: I0908 08:17:24.183428 852 shared_informer.go:377] "Caches are synced"1553machine # [ 39.320697] k3s[852]: I0908 08:17:24.183481 852 shared_informer.go:377] "Caches are synced"1554machine # [ 39.332000] k3s[852]: time="2026-09-08T08:17:24Z" 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=Normal1555machine # [ 39.383636] k3s[852]: I0908 08:17:24.247583 852 server.go:264] "kube-proxy running in dual-stack mode" primary ipFamily="IPv4"1556machine # [ 39.390397] k3s[852]: I0908 08:17:24.247717 852 server_linux.go:136] "Using iptables Proxier"1557machine # [ 39.405450] k3s[852]: I0908 08:17:24.269925 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"config-volume\" (UniqueName: \"kubernetes.io/configmap/2be0bc03-8b4f-41cc-b617-2ee89db3d726-config-volume\") pod \"coredns-c5fdd76cf-m5mrr\" (UID: \"2be0bc03-8b4f-41cc-b617-2ee89db3d726\") " pod="kube-system/coredns-c5fdd76cf-m5mrr"1558machine # [ 39.416870] k3s[852]: I0908 08:17:24.278143 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"custom-config-volume\" (UniqueName: \"kubernetes.io/configmap/2be0bc03-8b4f-41cc-b617-2ee89db3d726-custom-config-volume\") pod \"coredns-c5fdd76cf-m5mrr\" (UID: \"2be0bc03-8b4f-41cc-b617-2ee89db3d726\") " pod="kube-system/coredns-c5fdd76cf-m5mrr"1559machine # [ 39.422531] k3s[852]: I0908 08:17:24.278181 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-zrzr2\" (UniqueName: \"kubernetes.io/projected/2be0bc03-8b4f-41cc-b617-2ee89db3d726-kube-api-access-zrzr2\") pod \"coredns-c5fdd76cf-m5mrr\" (UID: \"2be0bc03-8b4f-41cc-b617-2ee89db3d726\") " pod="kube-system/coredns-c5fdd76cf-m5mrr"1560machine # [ 39.428861] systemd[1]: Created slice libcontainer container kubepods-burstable-pod2be0bc03_8b4f_41cc_b617_2ee89db3d726.slice.1561machine # Error from server (NotFound): namespaces "niks3" not found1562machine # [ 39.498835] k3s[852]: time="2026-09-08T08:17:24Z" level=info msg="Imported docker.io/library/niks3-server:1.4.0-aarch64-linux"1563machine # [ 39.501578] k3s[852]: I0908 08:17:24.365073 852 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"1564machine # [ 39.506062] k3s[852]: time="2026-09-08T08:17:24Z" level=info msg="Tagged docker.io/library/niks3-server@sha256:ef8b88146ebad08002f9e4d2aac23808a837811ab0b214e882cf0e8d3c42d2de"1565machine # [ 39.536502] k3s[852]: I0908 08:17:24.400929 852 server.go:529] "Version info" version="v1.35.8+k3s1"1566machine # [ 39.538641] k3s[852]: I0908 08:17:24.401617 852 server.go:531] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1567machine # [ 39.541622] k3s[852]: I0908 08:17:24.403348 852 config.go:200] "Starting service config controller"1568machine # [ 39.542959] k3s[852]: I0908 08:17:24.403386 852 shared_informer.go:349] "Waiting for caches to sync" controller="service config"1569machine # [ 39.546080] k3s[852]: I0908 08:17:24.403410 852 config.go:106] "Starting endpoint slice config controller"1570machine # [ 39.548790] k3s[852]: I0908 08:17:24.403421 852 shared_informer.go:349] "Waiting for caches to sync" controller="endpoint slice config"1571machine # [ 39.550857] k3s[852]: I0908 08:17:24.403448 852 config.go:403] "Starting serviceCIDR config controller"1572machine # [ 39.552212] k3s[852]: I0908 08:17:24.403463 852 shared_informer.go:349] "Waiting for caches to sync" controller="serviceCIDR config"1573machine # [ 39.554931] k3s[852]: I0908 08:17:24.404409 852 config.go:309] "Starting node config controller"1574machine # [ 39.556928] k3s[852]: I0908 08:17:24.404435 852 shared_informer.go:349] "Waiting for caches to sync" controller="node config"1575machine # [ 39.558813] k3s[852]: I0908 08:17:24.404445 852 shared_informer.go:356] "Caches are synced" controller="node config"1576machine # [ 39.575633] k3s[852]: time="2026-09-08T08:17:24Z" level=info msg="Imported 1 images from /var/lib/rancher/k3s/agent/images/niks3-server.tar in 1.98437824s"1577machine # [ 39.589009] k3s[852]: time="2026-09-08T08:17:24Z" 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=Normal1578machine # [ 39.614361] k3s[852]: time="2026-09-08T08:17:24Z" 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=Normal1579machine # [ 39.636639] k3s[852]: time="2026-09-08T08:17:24Z" 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=Normal1580machine # [ 39.641423] k3s[852]: I0908 08:17:24.503619 852 shared_informer.go:356] "Caches are synced" controller="serviceCIDR config"1581machine # [ 39.642967] k3s[852]: I0908 08:17:24.503699 852 shared_informer.go:356] "Caches are synced" controller="service config"1582machine # [ 39.644611] k3s[852]: I0908 08:17:24.503750 852 shared_informer.go:356] "Caches are synced" controller="endpoint slice config"1583machine # [ 39.663636] k3s[852]: I0908 08:17:24.528040 852 controller.go:667] quota admission added evaluator for: jobs.batch1584machine # [ 39.728286] k3s[852]: time="2026-09-08T08:17:24Z" level=info msg="Tunnel authorizer set Kubelet Port 0.0.0.0:10250"1585machine # [ 39.808336] k3s[852]: time="2026-09-08T08:17:24Z" 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=Normal1586machine # [ 39.840193] k3s[852]: time="2026-09-08T08:17:24Z" 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=Normal1587machine # [ 39.920480] k3s[852]: time="2026-09-08T08:17:24Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Deleting manifest at \"/var/lib/rancher/k3s/server/manifests/traefik.yaml\"" object=kube-system/traefik reason=DeletingManifest type=Normal1588machine # [ 39.926062] k3s[852]: I0908 08:17:24.789612 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-tmp\") pod \"helm-install-niks3-msr2v\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") " pod="kube-system/helm-install-niks3-msr2v"1589machine # [ 39.930694] k3s[852]: I0908 08:17:24.793256 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"values\" (UniqueName: \"kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-values\") pod \"helm-install-niks3-msr2v\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") " pod="kube-system/helm-install-niks3-msr2v"1590machine # [ 39.940416] k3s[852]: I0908 08:17:24.793322 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-5dpzl\" (UniqueName: \"kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-kube-api-access-5dpzl\") pod \"helm-install-niks3-msr2v\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") " pod="kube-system/helm-install-niks3-msr2v"1591machine # [ 39.951281] k3s[852]: I0908 08:17:24.793378 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-helm\") pod \"helm-install-niks3-msr2v\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") " pod="kube-system/helm-install-niks3-msr2v"1592machine # [ 39.958061] k3s[852]: I0908 08:17:24.793398 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-cache\") pod \"helm-install-niks3-msr2v\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") " pod="kube-system/helm-install-niks3-msr2v"1593machine # [ 39.962601] k3s[852]: I0908 08:17:24.793431 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"content\" (UniqueName: \"kubernetes.io/configmap/65482376-8da7-4e27-97f2-d58aa4f0d011-content\") pod \"helm-install-niks3-msr2v\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") " pod="kube-system/helm-install-niks3-msr2v"1594machine # [ 39.967334] k3s[852]: I0908 08:17:24.793459 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-config\") pod \"helm-install-niks3-msr2v\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") " pod="kube-system/helm-install-niks3-msr2v"1595machine # [ 39.972728] systemd[1]: Created slice libcontainer container kubepods-burstable-pod65482376_8da7_4e27_97f2_d58aa4f0d011.slice.1596machine # [ 39.979539] k3s[852]: time="2026-09-08T08:17:24Z" level=info msg="Flannel found PodCIDR assigned for node machine"1597machine # [ 39.982218] k3s[852]: time="2026-09-08T08:17:24Z" level=info msg="The interface eth0 with ipv4 address 10.0.2.15 will be used by flannel"1598machine # [ 39.985129] k3s[852]: I0908 08:17:24.846855 852 kube.go:139] Waiting 10m0s for node controller to sync1599machine # [ 39.986440] k3s[852]: I0908 08:17:24.847082 852 kube.go:537] Starting kube subnet manager1600machine # [ 40.125201] k3s[852]: E0908 08:17:24.989511 852 log.go:32] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"42c57ffb83b6c4af19d581a26937a885d71286142ff964f13305419fb6bb0950\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory"1601machine # [ 40.130312] k3s[852]: E0908 08:17:24.989696 852 kuberuntime_sandbox.go:71] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"42c57ffb83b6c4af19d581a26937a885d71286142ff964f13305419fb6bb0950\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-c5fdd76cf-m5mrr"1602machine # [ 40.137498] k3s[852]: E0908 08:17:24.989795 852 kuberuntime_manager.go:1568] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"42c57ffb83b6c4af19d581a26937a885d71286142ff964f13305419fb6bb0950\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-c5fdd76cf-m5mrr"1603machine # [ 40.146211] k3s[852]: E0908 08:17:24.989959 852 pod_workers.go:1324] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"coredns-c5fdd76cf-m5mrr_kube-system(2be0bc03-8b4f-41cc-b617-2ee89db3d726)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"coredns-c5fdd76cf-m5mrr_kube-system(2be0bc03-8b4f-41cc-b617-2ee89db3d726)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"42c57ffb83b6c4af19d581a26937a885d71286142ff964f13305419fb6bb0950\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/coredns-c5fdd76cf-m5mrr" podUID="2be0bc03-8b4f-41cc-b617-2ee89db3d726"1604machine # [ 40.379946] k3s[852]: E0908 08:17:25.243557 852 log.go:32] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"e73247a4e0820927f2555a8d93bb5a3c0170e21020fb3bb704cb1cbe908543b5\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory"1605machine # [ 40.386331] k3s[852]: E0908 08:17:25.243752 852 kuberuntime_sandbox.go:71] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"e73247a4e0820927f2555a8d93bb5a3c0170e21020fb3bb704cb1cbe908543b5\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-msr2v"1606machine # [ 40.393717] k3s[852]: E0908 08:17:25.243804 852 kuberuntime_manager.go:1568] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"e73247a4e0820927f2555a8d93bb5a3c0170e21020fb3bb704cb1cbe908543b5\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-msr2v"1607machine # [ 40.403815] k3s[852]: E0908 08:17:25.243954 852 pod_workers.go:1324] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"helm-install-niks3-msr2v_kube-system(65482376-8da7-4e27-97f2-d58aa4f0d011)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"helm-install-niks3-msr2v_kube-system(65482376-8da7-4e27-97f2-d58aa4f0d011)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"e73247a4e0820927f2555a8d93bb5a3c0170e21020fb3bb704cb1cbe908543b5\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/helm-install-niks3-msr2v" podUID="65482376-8da7-4e27-97f2-d58aa4f0d011"1608machine # [ 40.612697] systemd[1]: run-netns-cni\x2d884a4150\x2d2a5f\x2d16ed\x2d6d94\x2d7e97c7b9bb27.mount: Deactivated successfully.1609machine # Error from server (NotFound): namespaces "niks3" not found1610machine # [ 40.982602] k3s[852]: I0908 08:17:25.847047 852 kube.go:163] Node controller sync successful1611machine # [ 40.984790] k3s[852]: I0908 08:17:25.847235 852 vxlan.go:128] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false1612machine # [ 40.989915] k3s[852]: I0908 08:17:25.853207 852 kube.go:704] List of node(machine) annotations: map[string]string{"alpha.kubernetes.io/provided-node-ip":"10.0.2.15,fec0::a63e:f22e:72a2:90f0", "k3s.io/hostname":"machine", "k3s.io/internal-ip":"10.0.2.15,fec0::a63e:f22e:72a2:90f0", "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"}1613machine # [ 41.043173] (udev-worker)[1056]: Network interface NamePolicy= disabled on kernel command line.1614machine # [ 41.075448] k3s[852]: I0908 08:17:25.939881 852 kube.go:558] Creating the node lease for IPv4. This is the n.Spec.PodCIDRs: [10.42.0.0/24]1615machine # [ 41.078665] k3s[852]: I0908 08:17:25.941140 852 iptables.go:50] Starting flannel in iptables mode...1616machine # [ 41.080516] k3s[852]: time="2026-09-08T08:17:25Z" level=warning msg="no subnet found for key: FLANNEL_NETWORK in file: /run/flannel/subnet.env"1617machine # [ 41.086809] k3s[852]: time="2026-09-08T08:17:25Z" level=warning msg="no subnet found for key: FLANNEL_SUBNET in file: /run/flannel/subnet.env"1618machine # [ 41.090495] k3s[852]: time="2026-09-08T08:17:25Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_NETWORK in file: /run/flannel/subnet.env"1619machine # [ 41.094060] k3s[852]: time="2026-09-08T08:17:25Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_SUBNET in file: /run/flannel/subnet.env"1620machine # [ 41.096931] k3s[852]: I0908 08:17:25.941651 852 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 rules1621machine # [ 41.121455] dhcpcd[610]: flannel.1: IAID ab:54:76:c91622machine # [ 41.122806] dhcpcd[610]: flannel.1: adding address fe80::c41e:abff:fe54:76c91623machine # [ 41.197493] k3s[852]: I0908 08:17:26.061721 852 iptables.go:111] Setting up masking rules1624machine # [ 41.225461] k3s[852]: I0908 08:17:26.089913 852 iptables.go:212] Changing default FORWARD chain policy to ACCEPT1625machine # [ 41.250249] k3s[852]: time="2026-09-08T08:17:26Z" level=info msg="Wrote flannel subnet file to /run/flannel/subnet.env"1626machine # [ 41.254068] k3s[852]: time="2026-09-08T08:17:26Z" level=info msg="Running flannel backend"1627machine # [ 41.255406] k3s[852]: I0908 08:17:26.114633 852 vxlan_network.go:68] watching for new subnet leases1628machine # [ 41.258427] k3s[852]: I0908 08:17:26.114664 852 vxlan_network.go:115] starting vxlan device watcher1629machine # [ 41.346446] k3s[852]: I0908 08:17:26.210928 852 iptables.go:358] bootstrap done1630machine # [ 41.410970] k3s[852]: I0908 08:17:26.274971 852 iptables.go:358] bootstrap done1631machine # [ 41.653116] k3s[852]: I0908 08:17:26.516716 852 node_lifecycle_controller.go:1234] "Initializing eviction metric for zone" zone=""1632machine # [ 41.656838] k3s[852]: I0908 08:17:26.516977 852 node_lifecycle_controller.go:886] "Missing timestamp for Node. Assuming now as a timestamp" node="machine"1633machine # [ 41.660838] k3s[852]: I0908 08:17:26.517079 852 node_lifecycle_controller.go:1080] "Controller detected that zone is now in new state" zone="" newState="Normal"1634machine # [ 42.155445] dhcpcd[610]: flannel.1: soliciting a DHCP lease1635machine # Error from server (NotFound): namespaces "niks3" not found1636machine # [ 42.826502] k3s[852]: time="2026-09-08T08:17:27Z" level=info msg="Started tunnel to 10.0.2.15:6443"1637machine # [ 42.830877] k3s[852]: time="2026-09-08T08:17:27Z" level=info msg="Connecting to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1638machine # [ 42.837200] k3s[852]: time="2026-09-08T08:17:27Z" level=info msg="Stopped tunnel to 127.0.0.1:6443"1639machine # [ 42.841695] k3s[852]: time="2026-09-08T08:17:27Z" level=info msg="Proxy done" err="context canceled" url="wss://127.0.0.1:6443/v1-k3s/connect"1640machine # [ 42.847235] k3s[852]: time="2026-09-08T08:17:27Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF"1641machine # [ 42.853576] dhcpcd[610]: flannel.1: soliciting an IPv6 router1642machine # [ 42.856427] k3s[852]: time="2026-09-08T08:17:27Z" level=info msg="Handling backend connection request [machine]"1643machine # [ 42.860853] k3s[852]: time="2026-09-08T08:17:27Z" level=info msg="Connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1644machine # [ 42.865776] k3s[852]: time="2026-09-08T08:17:27Z" level=info msg="Remotedialer connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1645machine # Error from server (NotFound): namespaces "niks3" not found1646machine # Error from server (NotFound): namespaces "niks3" not found1647machine # Error from server (NotFound): namespaces "niks3" not found1648machine # [ 47.156066] dhcpcd[610]: flannel.1: probing for an IPv4LL address1649machine # Error from server (NotFound): namespaces "niks3" not found1650machine # Error from server (NotFound): namespaces "niks3" not found1651machine # Error from server (NotFound): namespaces "niks3" not found1652machine # [ 51.890790] dhcpcd[610]: flannel.1: using IPv4LL address 169.254.108.491653machine # [ 51.895562] dhcpcd[610]: flannel.1: adding route to 169.254.0.0/161654machine # Error from server (NotFound): namespaces "niks3" not found1655machine # [ 52.703049] cni0: port 1(vethdb1eaf9c) entered blocking state1656machine # [ 52.703120] cni0: port 1(vethdb1eaf9c) entered disabled state1657machine # [ 52.703168] vethdb1eaf9c: entered allmulticast mode1658machine # [ 52.703353] vethdb1eaf9c: entered promiscuous mode1659machine # [ 52.740859] cni0: port 1(vethdb1eaf9c) entered blocking state1660machine # [ 52.740944] cni0: port 1(vethdb1eaf9c) entered forwarding state1661machine # [ 52.824633] (udev-worker)[1508]: Network interface NamePolicy= disabled on kernel command line.1662machine # [ 52.827795] (udev-worker)[1510]: Network interface NamePolicy= disabled on kernel command line.1663machine # [ 52.851801] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount4031557972.mount: Deactivated successfully.1664machine # [ 52.893757] dhcpcd[610]: vethdb1eaf9c: IAID f8:00:77:e91665machine # [ 52.895055] dhcpcd[610]: vethdb1eaf9c: adding address fe80::2ca7:f8ff:fe00:77e91666machine # [ 52.972543] systemd[1]: Started libcontainer container ff9e883badc2c8447b40cbc03f8320840eb93cbfd5c658ddf499c0ab27e11600.1667machine # Error from server (NotFound): namespaces "niks3" not found1668machine # [ 53.692230] dhcpcd[610]: vethdb1eaf9c: soliciting a DHCP lease1669machine # [ 53.929616] systemd[1]: Started libcontainer container 079b62b06324ff56995ea06899303caa71c2d70da9931fede87a24df6e89d907.1670machine # [ 54.531027] dhcpcd[610]: vethdb1eaf9c: soliciting an IPv6 router1671machine # [ 54.742297] k3s[852]: I0908 08:17:39.606176 852 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/coredns-c5fdd76cf-m5mrr" podStartSLOduration=17.60615366 podStartE2EDuration="17.60615366s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-08 08:17:22 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-08 08:17:39.60586784 +0000 UTC m=+31.726422821" watchObservedRunningTime="2026-09-08 08:17:39.60615366 +0000 UTC m=+31.726708641"1672machine # [ 54.836906] dhcpcd[610]: flannel.1: no IPv6 Routers available1673machine # Error from server (NotFound): namespaces "niks3" not found1674machine # [ 55.661387] (udev-worker)[1516]: Network interface NamePolicy= disabled on kernel command line.1675machine # [ 55.667912] cni0: port 2(veth9ebdf1c7) entered blocking state1676machine # [ 55.667985] cni0: port 2(veth9ebdf1c7) entered disabled state1677machine # [ 55.668076] veth9ebdf1c7: entered allmulticast mode1678machine # [ 55.668304] veth9ebdf1c7: entered promiscuous mode1679machine # [ 55.709295] cni0: port 2(veth9ebdf1c7) entered blocking state1680machine # [ 55.709379] cni0: port 2(veth9ebdf1c7) entered forwarding state1681machine # [ 55.756161] dhcpcd[610]: veth9ebdf1c7: IAID fd:23:0d:ce1682machine # [ 55.758492] dhcpcd[610]: veth9ebdf1c7: adding address fe80::90cb:fdff:fe23:dce1683machine # [ 55.885115] systemd[1]: Started libcontainer container e636f607587a5e6bc91a65eb13608c601cbf0f8fe0db38cb93c04bad9b89275b.1684machine # Error from server (NotFound): namespaces "niks3" not found1685machine # [ 56.279614] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount502724502.mount: Deactivated successfully.1686machine # [ 56.359420] dhcpcd[610]: veth9ebdf1c7: soliciting a DHCP lease1687machine # [ 57.239434] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount3076125731.mount: Deactivated successfully.1688machine # [ 57.300573] systemd[1]: Started libcontainer container a886a0d30bcf508c91a088d143f8472023f48cc2292072bdb1b0ffa5a997e7ea.1689machine # [ 57.454440] dhcpcd[610]: veth9ebdf1c7: soliciting an IPv6 router1690machine # Error from server (NotFound): namespaces "niks3" not found1691machine # [ 57.763014] k3s[852]: I0908 08:17:42.626179 852 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/helm-install-niks3-msr2v" podStartSLOduration=18.62613622 podStartE2EDuration="18.62613622s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-08 08:17:24 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-08 08:17:42.62589392 +0000 UTC m=+34.746448941" watchObservedRunningTime="2026-09-08 08:17:42.62613622 +0000 UTC m=+34.746691241"1692machine # [ 58.693034] dhcpcd[610]: vethdb1eaf9c: probing for an IPv4LL address1693machine # Error from server (NotFound): deployments.apps "niks3" not found1694machine # [ 58.947298] k3s[852]: I0908 08:17:43.811235 852 alloc.go:329] "allocated clusterIPs" service="niks3/niks3" clusterIPs={"IPv4":"10.43.53.196"}1695machine # [ 58.977064] k3s[852]: I0908 08:17:43.841560 852 controller.go:667] quota admission added evaluator for: cronjobs.batch1696machine # [ 59.008121] systemd[1]: cri-containerd-a886a0d30bcf508c91a088d143f8472023f48cc2292072bdb1b0ffa5a997e7ea.scope: Deactivated successfully.1697machine # [ 59.010742] systemd[1]: cri-containerd-a886a0d30bcf508c91a088d143f8472023f48cc2292072bdb1b0ffa5a997e7ea.scope: Consumed 1.002s CPU time over 1.707s wall clock time, 38.4M memory peak, 4.1M incoming IP traffic, 77.7K outgoing IP traffic.1698machine # [ 59.060537] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-a886a0d30bcf508c91a088d143f8472023f48cc2292072bdb1b0ffa5a997e7ea-rootfs.mount: Deactivated successfully.1699machine # [ 59.253898] systemd[1]: Created slice libcontainer container kubepods-besteffort-poded193a0f_2bb4_4251_a72f_42e471609bf1.slice.1700machine # [ 59.315734] k3s[852]: I0908 08:17:44.180092 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"db\" (UniqueName: \"kubernetes.io/secret/ed193a0f-2bb4-4251-a72f-42e471609bf1-db\") pod \"niks3-5c78d87487-lpvdb\" (UID: \"ed193a0f-2bb4-4251-a72f-42e471609bf1\") " pod="niks3/niks3-5c78d87487-lpvdb"1701machine # [ 59.327936] k3s[852]: I0908 08:17:44.180197 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-h2b7b\" (UniqueName: \"kubernetes.io/projected/ed193a0f-2bb4-4251-a72f-42e471609bf1-kube-api-access-h2b7b\") pod \"niks3-5c78d87487-lpvdb\" (UID: \"ed193a0f-2bb4-4251-a72f-42e471609bf1\") " pod="niks3/niks3-5c78d87487-lpvdb"1702machine # [ 59.339755] k3s[852]: I0908 08:17:44.180253 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"oidc\" (UniqueName: \"kubernetes.io/configmap/ed193a0f-2bb4-4251-a72f-42e471609bf1-oidc\") pod \"niks3-5c78d87487-lpvdb\" (UID: \"ed193a0f-2bb4-4251-a72f-42e471609bf1\") " pod="niks3/niks3-5c78d87487-lpvdb"1703machine # [ 59.349274] k3s[852]: I0908 08:17:44.180293 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/ed193a0f-2bb4-4251-a72f-42e471609bf1-token\") pod \"niks3-5c78d87487-lpvdb\" (UID: \"ed193a0f-2bb4-4251-a72f-42e471609bf1\") " pod="niks3/niks3-5c78d87487-lpvdb"1704machine # [ 59.358771] k3s[852]: I0908 08:17:44.180334 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"s3\" (UniqueName: \"kubernetes.io/secret/ed193a0f-2bb4-4251-a72f-42e471609bf1-s3\") pod \"niks3-5c78d87487-lpvdb\" (UID: \"ed193a0f-2bb4-4251-a72f-42e471609bf1\") " pod="niks3/niks3-5c78d87487-lpvdb"1705machine # [ 59.939412] cni0: port 3(veth202e033e) entered blocking state1706machine # [ 59.939507] cni0: port 3(veth202e033e) entered disabled state1707machine # [ 59.939563] veth202e033e: entered allmulticast mode1708machine # [ 59.939792] veth202e033e: entered promiscuous mode1709machine # [ 59.976968] cni0: port 3(veth202e033e) entered blocking state1710machine # [ 59.977034] cni0: port 3(veth202e033e) entered forwarding state1711machine # [ 60.105275] (udev-worker)[1895]: Network interface NamePolicy= disabled on kernel command line.1712machine # [ 60.193625] dhcpcd[610]: veth202e033e: IAID 1b:03:b8:301713machine # [ 60.194531] dhcpcd[610]: veth202e033e: adding address fe80::241d:1bff:fe03:b8301714machine # [ 60.201516] systemd[1]: Started libcontainer container d3022d99bc609aa18070fb46b6022d3c26b49a9cf0be27d3a6b6d0e32d3425e9.1715machine # [ 60.301288] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount1339658668.mount: Deactivated successfully.1716machine # [ 60.768534] systemd[1]: Started libcontainer container 4e49bd251986cafe67534d5727f2de9691561aae50cbdddd8c9f35aa8f8f4f41.1717machine # [ 60.774692] systemd[1]: cri-containerd-e636f607587a5e6bc91a65eb13608c601cbf0f8fe0db38cb93c04bad9b89275b.scope: Deactivated successfully.1718machine # [ 60.895640] postgres[2006]: [2006] ERROR: relation "goose_db_version" does not exist at character 361719machine # [ 60.897536] postgres[2006]: [2006] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1720machine # [ 60.927554] dhcpcd[610]: veth202e033e: soliciting a DHCP lease1721machine # [ 61.033018] cni0: port 2(veth9ebdf1c7) entered disabled state1722machine # [ 61.030678] dhcpcd[610]: veth9ebdf1c7: carrier lost1723machine # [ 61.037104] veth9ebdf1c7 (unregistering): left allmulticast mode1724machine # [ 61.037143] veth9ebdf1c7 (unregistering): left promiscuous mode1725machine # [ 61.037177] cni0: port 2(veth9ebdf1c7) entered disabled state1726machine # [ 61.100319] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-e636f607587a5e6bc91a65eb13608c601cbf0f8fe0db38cb93c04bad9b89275b-rootfs.mount: Deactivated successfully.1727machine # [ 61.105871] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-e636f607587a5e6bc91a65eb13608c601cbf0f8fe0db38cb93c04bad9b89275b-shm.mount: Deactivated successfully.1728machine # [ 61.110122] systemd[1]: run-netns-cni\x2d3750d4ed\x2d5b9c\x2d1bc3\x2d177d\x2dd9af7f27cd74.mount: Deactivated successfully.1729machine # [ 61.115381] dhcpcd[610]: veth9ebdf1c7: deleting address fe80::90cb:fdff:fe23:dce1730machine # [ 61.128890] k3s[852]: I0908 08:17:45.992064 852 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-config\") pod \"65482376-8da7-4e27-97f2-d58aa4f0d011\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") "1731machine # [ 61.133786] k3s[852]: I0908 08:17:45.992131 852 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-values\" (UniqueName: \"kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-values\") pod \"65482376-8da7-4e27-97f2-d58aa4f0d011\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") "1732machine # [ 61.138298] k3s[852]: I0908 08:17:45.992184 852 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-helm\") pod \"65482376-8da7-4e27-97f2-d58aa4f0d011\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") "1733machine # [ 61.143115] k3s[852]: I0908 08:17:45.992246 852 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-kube-api-access-5dpzl\" (UniqueName: \"kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-kube-api-access-5dpzl\") pod \"65482376-8da7-4e27-97f2-d58aa4f0d011\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") "1734machine # [ 61.148468] k3s[852]: I0908 08:17:45.992275 852 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-cache\") pod \"65482376-8da7-4e27-97f2-d58aa4f0d011\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") "1735machine # [ 61.153928] k3s[852]: I0908 08:17:45.992296 852 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-tmp\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-tmp\") pod \"65482376-8da7-4e27-97f2-d58aa4f0d011\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") "1736machine # [ 61.158642] k3s[852]: I0908 08:17:45.992317 852 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/configmap/65482376-8da7-4e27-97f2-d58aa4f0d011-content\" (UniqueName: \"kubernetes.io/configmap/65482376-8da7-4e27-97f2-d58aa4f0d011-content\") pod \"65482376-8da7-4e27-97f2-d58aa4f0d011\" (UID: \"65482376-8da7-4e27-97f2-d58aa4f0d011\") "1737machine # [ 61.166917] k3s[852]: I0908 08:17:45.992903 852 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/configmap/65482376-8da7-4e27-97f2-d58aa4f0d011-content" pod "65482376-8da7-4e27-97f2-d58aa4f0d011" (UID: "65482376-8da7-4e27-97f2-d58aa4f0d011"). InnerVolumeSpecName "content". PluginName "kubernetes.io/configmap", VolumeGIDValue ""1738machine # [ 61.174571] systemd[1]: var-lib-kubelet-pods-65482376\x2d8da7\x2d4e27\x2d97f2\x2dd58aa4f0d011-volumes-kubernetes.io\x7eprojected-values.mount: Deactivated successfully.1739machine # [ 61.177893] systemd[1]: var-lib-kubelet-pods-65482376\x2d8da7\x2d4e27\x2d97f2\x2dd58aa4f0d011-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dconfig.mount: Deactivated successfully.1740machine # [ 61.182135] k3s[852]: I0908 08:17:46.046641 852 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-values" pod "65482376-8da7-4e27-97f2-d58aa4f0d011" (UID: "65482376-8da7-4e27-97f2-d58aa4f0d011"). InnerVolumeSpecName "values". PluginName "kubernetes.io/projected", VolumeGIDValue ""1741machine # [ 61.188316] k3s[852]: I0908 08:17:46.052820 852 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-config" pod "65482376-8da7-4e27-97f2-d58aa4f0d011" (UID: "65482376-8da7-4e27-97f2-d58aa4f0d011"). InnerVolumeSpecName "klipper-config". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1742machine # [ 61.195407] k3s[852]: I0908 08:17:46.059687 852 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-cache" pod "65482376-8da7-4e27-97f2-d58aa4f0d011" (UID: "65482376-8da7-4e27-97f2-d58aa4f0d011"). InnerVolumeSpecName "klipper-cache". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1743machine # [ 61.203159] systemd[1]: var-lib-kubelet-pods-65482376\x2d8da7\x2d4e27\x2d97f2\x2dd58aa4f0d011-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dcache.mount: Deactivated successfully.1744machine # [ 61.208407] k3s[852]: I0908 08:17:46.064725 852 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-helm" pod "65482376-8da7-4e27-97f2-d58aa4f0d011" (UID: "65482376-8da7-4e27-97f2-d58aa4f0d011"). InnerVolumeSpecName "klipper-helm". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1745machine # [ 61.215994] k3s[852]: I0908 08:17:46.068449 852 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-tmp" pod "65482376-8da7-4e27-97f2-d58aa4f0d011" (UID: "65482376-8da7-4e27-97f2-d58aa4f0d011"). InnerVolumeSpecName "tmp". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1746machine # [ 61.225424] k3s[852]: I0908 08:17:46.068694 852 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-kube-api-access-5dpzl" pod "65482376-8da7-4e27-97f2-d58aa4f0d011" (UID: "65482376-8da7-4e27-97f2-d58aa4f0d011"). InnerVolumeSpecName "kube-api-access-5dpzl". PluginName "kubernetes.io/projected", VolumeGIDValue ""1747machine # [ 61.235242] systemd[1]: var-lib-kubelet-pods-65482376\x2d8da7\x2d4e27\x2d97f2\x2dd58aa4f0d011-volumes-kubernetes.io\x7eprojected-kube\x2dapi\x2daccess\x2d5dpzl.mount: Deactivated successfully.1748machine # [ 61.239086] k3s[852]: I0908 08:17:46.092753 852 reconciler_common.go:299] "Volume detached for volume \"kube-api-access-5dpzl\" (UniqueName: \"kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-kube-api-access-5dpzl\") on node \"machine\" DevicePath \"\""1749machine # [ 61.243030] k3s[852]: I0908 08:17:46.092782 852 reconciler_common.go:299] "Volume detached for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-cache\") on node \"machine\" DevicePath \"\""1750machine # [ 61.246732] k3s[852]: I0908 08:17:46.092793 852 reconciler_common.go:299] "Volume detached for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-tmp\") on node \"machine\" DevicePath \"\""1751machine # [ 61.250187] k3s[852]: I0908 08:17:46.092803 852 reconciler_common.go:299] "Volume detached for volume \"content\" (UniqueName: \"kubernetes.io/configmap/65482376-8da7-4e27-97f2-d58aa4f0d011-content\") on node \"machine\" DevicePath \"\""1752machine # [ 61.253560] k3s[852]: I0908 08:17:46.092812 852 reconciler_common.go:299] "Volume detached for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-config\") on node \"machine\" DevicePath \"\""1753machine # [ 61.257099] k3s[852]: I0908 08:17:46.092821 852 reconciler_common.go:299] "Volume detached for volume \"values\" (UniqueName: \"kubernetes.io/projected/65482376-8da7-4e27-97f2-d58aa4f0d011-values\") on node \"machine\" DevicePath \"\""1754machine # [ 61.260326] k3s[852]: I0908 08:17:46.092830 852 reconciler_common.go:299] "Volume detached for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/65482376-8da7-4e27-97f2-d58aa4f0d011-klipper-helm\") on node \"machine\" DevicePath \"\""1755machine # [ 61.263571] systemd[1]: var-lib-kubelet-pods-65482376\x2d8da7\x2d4e27\x2d97f2\x2dd58aa4f0d011-volumes-kubernetes.io\x7eempty\x2ddir-tmp.mount: Deactivated successfully.1756machine # [ 61.265882] systemd[1]: var-lib-kubelet-pods-65482376\x2d8da7\x2d4e27\x2d97f2\x2dd58aa4f0d011-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dhelm.mount: Deactivated successfully.1757machine # [ 61.272926] dhcpcd[610]: veth9ebdf1c7: removing interface1758machine # [ 61.483955] dhcpcd[610]: veth202e033e: soliciting an IPv6 router1759machine # [ 61.760252] k3s[852]: I0908 08:17:46.621636 852 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="e636f607587a5e6bc91a65eb13608c601cbf0f8fe0db38cb93c04bad9b89275b"1760machine # [ 61.790565] systemd[1]: Removed slice libcontainer container kubepods-burstable-pod65482376_8da7_4e27_97f2_d58aa4f0d011.slice.1761machine # [ 61.797234] systemd[1]: kubepods-burstable-pod65482376_8da7_4e27_97f2_d58aa4f0d011.slice: Consumed 1.034s CPU time over 21.838s wall clock time, 38.7M memory peak, 4.1M incoming IP traffic, 77.7K outgoing IP traffic.1762machine # [ 62.143491] k3s[852]: I0908 08:17:47.006511 852 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/niks3-5c78d87487-lpvdb" podStartSLOduration=3.00646212 podStartE2EDuration="3.00646212s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-08 08:17:44 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-08 08:17:46.66711614 +0000 UTC m=+38.787671161" watchObservedRunningTime="2026-09-08 08:17:47.00646212 +0000 UTC m=+39.127017141"1763machine # [ 63.933468] dhcpcd[610]: vethdb1eaf9c: using IPv4LL address 169.254.218.1041764machine # [ 63.933886] dhcpcd[610]: vethdb1eaf9c: adding route to 169.254.0.0/161765machine # [ 65.928649] dhcpcd[610]: veth202e033e: probing for an IPv4LL address1766machine: (finished: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s, in 34.24 seconds)1767machine: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true1768machine: (finished: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true, in 0.28 seconds)1769machine: waiting for success: curl -sf http://localhost:30051/readyz | grep OK1770machine: (finished: waiting for success: curl -sf http://localhost:30051/readyz | grep OK, in 0.09 seconds)1771(finished: subtest: chart deploys and becomes ready, in 34.61 seconds)1772machine: waiting for success: kubectl -n ci get sa builder1773machine # [ 66.534163] dhcpcd[610]: vethdb1eaf9c: no IPv6 Routers available1774machine: (finished: waiting for success: kubectl -n ci get sa builder, in 0.26 seconds)1775machine: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt1776machine: (finished: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt, in 0.30 seconds)1777machine: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt1778machine: (finished: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt, in 0.32 seconds)1779machine: must succeed: readlink -f /run/current-system/sw/bin/niks31780machine: (finished: must succeed: readlink -f /run/current-system/sw/bin/niks3, in 0.04 seconds)1781subtest: allowed service account can push via workload identity1782machine: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/jr3qkr9yb8q4nc2rajmm2bp4fik2mq07-niks3-1.10.1 2>&11783machine: (finished: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/jr3qkr9yb8q4nc2rajmm2bp4fik2mq07-niks3-1.10.1 2>&1, in 1.77 seconds)1784machine: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/jr3qkr9yb8q4nc2rajmm2bp4fik2mq07.narinfo1785machine: (finished: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/jr3qkr9yb8q4nc2rajmm2bp4fik2mq07.narinfo, in 0.05 seconds)1786(finished: subtest: allowed service account can push via workload identity, in 1.82 seconds)1787subtest: write scope does not grant admin1788machine: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status1789machine: (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.06 seconds)1790(finished: subtest: write scope does not grant admin, in 0.06 seconds)1791subtest: other service accounts are rejected1792machine: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/jr3qkr9yb8q4nc2rajmm2bp4fik2mq07-niks3-1.10.1 2>&11793machine: (finished: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/jr3qkr9yb8q4nc2rajmm2bp4fik2mq07-niks3-1.10.1 2>&1, in 0.22 seconds)1794(finished: subtest: other service accounts are rejected, in 0.22 seconds)1795subtest: gc cronjob runs against the service1796machine: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual1797machine: (finished: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual, in 0.26 seconds)1798machine: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s1799machine # [ 69.639322] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod51931a31_190a_4770_b0ba_2b359a4d232a.slice.1800machine # [ 69.706623] k3s[852]: I0908 08:17:54.570709 852 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/51931a31-190a-4770-b0ba-2b359a4d232a-token\") pod \"gc-manual-c7ktx\" (UID: \"51931a31-190a-4770-b0ba-2b359a4d232a\") " pod="niks3/gc-manual-c7ktx"1801machine # [ 70.015062] cni0: port 2(veth2f71caf7) entered blocking state1802machine # [ 70.015121] cni0: port 2(veth2f71caf7) entered disabled state1803machine # [ 70.015193] veth2f71caf7: entered allmulticast mode1804machine # [ 70.015366] veth2f71caf7: entered promiscuous mode1805machine # [ 70.035180] cni0: port 2(veth2f71caf7) entered blocking state1806machine # [ 70.035227] cni0: port 2(veth2f71caf7) entered forwarding state1807machine # [ 70.141257] (udev-worker)[2300]: Network interface NamePolicy= disabled on kernel command line.1808machine # [ 70.205124] dhcpcd[610]: veth2f71caf7: IAID 6e:5a:46:171809machine # [ 70.206200] dhcpcd[610]: veth2f71caf7: adding address fe80::fc26:6eff:fe5a:46171810machine # [ 70.208348] systemd[1]: Started libcontainer container 769710a96e002d4727bd6b92aa27cd571e7bf6c10616f62a5180f25861bea2c1.1811machine # [ 70.235558] dhcpcd[610]: veth2f71caf7: soliciting a DHCP lease1812machine # [ 70.268877] k3s[852]: time="2026-09-08T08:17:55Z" level=info msg="Starting network policy controller version v2.6.3-k3s1, built on 1970-01-01T01:01:01Z, go1.26.7"1813machine # [ 70.272051] k3s[852]: I0908 08:17:55.133095 852 network_policy_controller.go:164] Starting network policy controller1814machine # [ 70.340483] systemd[1]: Started libcontainer container e71c3dc971b12939602cc8bdc5be3c11f88d7abe0112a15d339671ebe5c8b155.1815machine # [ 70.633751] k3s[852]: I0908 08:17:55.498177 852 network_policy_controller.go:179] Starting network policy controller full sync goroutine1816machine # [ 71.059935] dhcpcd[610]: veth202e033e: using IPv4LL address 169.254.72.911817machine # [ 71.063538] dhcpcd[610]: veth202e033e: adding route to 169.254.0.0/161818machine # [ 72.152433] dhcpcd[610]: veth2f71caf7: soliciting an IPv6 router1819machine # [ 72.421903] systemd[1]: cri-containerd-e71c3dc971b12939602cc8bdc5be3c11f88d7abe0112a15d339671ebe5c8b155.scope: Deactivated successfully.1820machine # [ 72.432196] systemd[1]: cri-containerd-e71c3dc971b12939602cc8bdc5be3c11f88d7abe0112a15d339671ebe5c8b155.scope: Consumed 35ms CPU time over 2.086s wall clock time, 4.1M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic.1821machine # [ 72.517595] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-e71c3dc971b12939602cc8bdc5be3c11f88d7abe0112a15d339671ebe5c8b155-rootfs.mount: Deactivated successfully.1822machine # [ 73.489291] dhcpcd[610]: veth202e033e: no IPv6 Routers available1823machine # [ 73.864906] systemd[1]: cri-containerd-769710a96e002d4727bd6b92aa27cd571e7bf6c10616f62a5180f25861bea2c1.scope: Deactivated successfully.1824machine # [ 73.954629] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-769710a96e002d4727bd6b92aa27cd571e7bf6c10616f62a5180f25861bea2c1-rootfs.mount: Deactivated successfully.1825machine # [ 74.010487] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-769710a96e002d4727bd6b92aa27cd571e7bf6c10616f62a5180f25861bea2c1-shm.mount: Deactivated successfully.1826machine # [ 74.086616] cni0: port 2(veth2f71caf7) entered disabled state1827machine # [ 74.086566] dhcpcd[610]: veth2f71caf7: carrier lost[ 74.089605] veth2f71caf7 (unregistering): left allmulticast mode1828machine # 1829machine # [ 74.089658] veth2f71caf7 (unregistering): left promiscuous mode1830machine # [ 74.089687] cni0: port 2(veth2f71caf7) entered disabled state1831machine # [ 74.124724] systemd[1]: run-netns-cni\x2dc636c70f\x2dbb9d\x2d66ae\x2dfe1c\x2de3f7d229d15d.mount: Deactivated successfully.1832machine # [ 74.181400] dhcpcd[610]: veth2f71caf7: deleting address fe80::fc26:6eff:fe5a:46171833machine # [ 74.240541] k3s[852]: I0908 08:17:59.104378 852 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/secret/51931a31-190a-4770-b0ba-2b359a4d232a-token\" (UniqueName: \"kubernetes.io/secret/51931a31-190a-4770-b0ba-2b359a4d232a-token\") pod \"51931a31-190a-4770-b0ba-2b359a4d232a\" (UID: \"51931a31-190a-4770-b0ba-2b359a4d232a\") "1834machine # [ 74.252881] systemd[1]: var-lib-kubelet-pods-51931a31\x2d190a\x2d4770\x2db0ba\x2d2b359a4d232a-volumes-kubernetes.io\x7esecret-token.mount: Deactivated successfully.1835machine # [ 74.255972] k3s[852]: I0908 08:17:59.117580 852 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/51931a31-190a-4770-b0ba-2b359a4d232a-token" pod "51931a31-190a-4770-b0ba-2b359a4d232a" (UID: "51931a31-190a-4770-b0ba-2b359a4d232a"). InnerVolumeSpecName "token". PluginName "kubernetes.io/secret", VolumeGIDValue ""1836machine # [ 74.264364] dhcpcd[610]: veth2f71caf7: removing interface1837machine # [ 74.340302] k3s[852]: I0908 08:17:59.204823 852 reconciler_common.go:299] "Volume detached for volume \"token\" (UniqueName: \"kubernetes.io/secret/51931a31-190a-4770-b0ba-2b359a4d232a-token\") on node \"machine\" DevicePath \"\""1838machine # [ 74.625352] systemd[1]: Removed slice libcontainer container kubepods-besteffort-pod51931a31_190a_4770_b0ba_2b359a4d232a.slice.1839machine # [ 74.630417] systemd[1]: kubepods-besteffort-pod51931a31_190a_4770_b0ba_2b359a4d232a.slice: Consumed 63ms CPU time over 4.985s wall clock time, 5.1M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic.1840machine # [ 74.829636] k3s[852]: I0908 08:17:59.693000 852 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="769710a96e002d4727bd6b92aa27cd571e7bf6c10616f62a5180f25861bea2c1"1841machine: (finished: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s, in 5.30 seconds)1842(finished: subtest: gc cronjob runs against the service, in 5.56 seconds)1843subtest: helm test hook passes1844machine: must succeed: helm test -n niks3 niks3 --timeout 2m >&21845machine # [ 75.977733] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod71f3829b_05ee_4cd9_9634_b1e1985e9fb6.slice.1846machine # [ 76.039516] cni0: port 2(veth1ad1effc) entered blocking state1847machine # [ 76.039564] cni0: port 2(veth1ad1effc) entered disabled state1848machine # [ 76.039609] veth1ad1effc: entered allmulticast mode1849machine # [ 76.039719] veth1ad1effc: entered promiscuous mode1850machine # [ 76.043059] (udev-worker)[2597]: Network interface NamePolicy= disabled on kernel command line.1851machine # [ 76.067075] cni0: port 2(veth1ad1effc) entered blocking state1852machine # [ 76.067122] cni0: port 2(veth1ad1effc) entered forwarding state1853machine # [ 76.112195] dhcpcd[610]: veth1ad1effc: IAID da:3e:61:ab1854machine # [ 76.114418] dhcpcd[610]: veth1ad1effc: adding address fe80::494:daff:fe3e:61ab1855machine # [ 76.204898] systemd[1]: Started libcontainer container 576828b069b0880faf211b7c833f3ae88088d504c0781010f67a2133b47b7499.1856machine # [ 76.348585] systemd[1]: Started libcontainer container eb2930c77fafb2a9dadad3884d69ddad24125abc417ca8d4b7a296fd32c6c0a4.1857machine # [ 76.424656] systemd[1]: cri-containerd-eb2930c77fafb2a9dadad3884d69ddad24125abc417ca8d4b7a296fd32c6c0a4.scope: Deactivated successfully.1858machine # [ 76.427661] systemd[1]: cri-containerd-eb2930c77fafb2a9dadad3884d69ddad24125abc417ca8d4b7a296fd32c6c0a4.scope: Consumed 30ms CPU time over 78ms wall clock time, 3.8M memory peak, 693B incoming IP traffic, 547B outgoing IP traffic.1859machine # [ 77.207433] dhcpcd[610]: veth1ad1effc: soliciting a DHCP lease1860machine # [ 77.609444] dhcpcd[610]: veth1ad1effc: soliciting an IPv6 router1861machine # [ 77.886303] systemd[1]: cri-containerd-576828b069b0880faf211b7c833f3ae88088d504c0781010f67a2133b47b7499.scope: Deactivated successfully.1862machine # [ 77.964608] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-576828b069b0880faf211b7c833f3ae88088d504c0781010f67a2133b47b7499-rootfs.mount: Deactivated successfully.1863machine # [ 78.030119] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-576828b069b0880faf211b7c833f3ae88088d504c0781010f67a2133b47b7499-shm.mount: Deactivated successfully.1864machine # [ 78.108713] dhcpcd[610]: veth1ad1effc: carrier lost[ 78.111729] cni0: port 2(veth1ad1effc) entered disabled state1865machine # 1866machine # [ 78.114705] veth1ad1effc (unregistering): left allmulticast mode1867machine # [ 78.114774] veth1ad1effc (unregistering): left promiscuous mode1868machine # [ 78.114802] cni0: port 2(veth1ad1effc) entered disabled state1869machine # [ 78.151463] systemd[1]: run-netns-cni\x2ddce77286\x2d7cee\x2d45a9\x2d466e\x2d5867511473f0.mount: Deactivated successfully.1870machine # [ 78.194581] dhcpcd[610]: veth1ad1effc: deleting address fe80::494:daff:fe3e:61ab1871machine # NAME: niks31872machine # LAST DEPLOYED: Tue Sep 8 08:17:43 20261873machine # NAMESPACE: niks31874machine # STATUS: deployed1875machine # REVISION: 11876machine # DESCRIPTION: Install complete1877machine # TEST SUITE: niks3-test1878machine # Last Started: Tue Sep 8 08:18:00 20261879machine # Last Completed: Tue Sep 8 08:18:03 20261880machine # Phase: Succeeded1881machine: (finished: must succeed: helm test -n niks3 niks3 --timeout 2m >&2, in 3.32 seconds)1882(finished: subtest: helm test hook passes, in 3.32 seconds)1883(finished: run the VM test script, in 79.03 seconds)1884test script finished in 79.09s1885cleanup1886kill QemuMachine (pid 45)1887machine # qemu-system-aarch64: terminating on signal 15 from pid 39 (/nix/store/lfh101cfjj8p8npcari9hk0lbqi33yvh-python3-3.14.7/bin/python3.14)1888(finished: cleanup, in 0.86 seconds)1889additionally exposed symbols:1890 machine,1891 vlan1,1892 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_ssh1893time=2026-09-08T08:17:52.491Z level=INFO msg="Uploading 8 paths to localhost (0 already cached)"1894time=2026-09-08T08:17:52.492Z level=INFO msg="Uploading lq5dy7clx12d63rp6yz8zwwpk8qdf736-libidn2-2.3.8 (366.1KB)"1895time=2026-09-08T08:17:52.492Z level=INFO msg="Uploading jr3qkr9yb8q4nc2rajmm2bp4fik2mq07-niks3-1.10.1 (7.0MB)"1896time=2026-09-08T08:17:52.496Z level=INFO msg="Uploading q7mfklgx6r8bm2ybkv0rj3vsgl71b1hf-libunistring-1.4.2 (2.0MB)"1897time=2026-09-08T08:17:52.496Z level=INFO msg="Uploading 9870dnbzywsgdi86yg1bc70aqwkqhxyp-tzdata-2026c (2.0MB)"1898time=2026-09-08T08:17:52.498Z level=INFO msg="Uploading fmraxa0v768xchpqr1iys6msnlhncjxy-iana-etc-20251215 (557.8KB)"1899time=2026-09-08T08:17:52.498Z level=INFO msg="Uploading h46id9241lp1g4zprx23fg6489x14lqb-xgcc-15.3.0-libgcc (150.1KB)"1900time=2026-09-08T08:17:52.499Z level=INFO msg="Uploading 6wjykzqf6w3kzfhjc4z7dcd84j0dzsgm-glibc-2.42-84 (44.4MB)"1901time=2026-09-08T08:17:52.501Z level=INFO msg="Uploading kp3ky28zd5hfmrgwygxlbrn1npj1a0cn-mailcap-2.1.54 (116.6KB)"1902time=2026-09-08T08:17:53.833Z level=INFO msg="Uploading 8 narinfos"1903time=2026-09-08T08:17:53.887Z level=INFO msg="Upload complete. (1.567s)"1904