vm-test-run-nixos-test-k3s
checks.aarch64-linux.nixos-test-k3s
· build #215
· 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.eR2lGDJzPw', 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: 18634b26-91c0-4be2-beef-b30608c30f9c17machine # Superblock backups stored on blocks:18machine # 32768, 98304, 163840, 229376, 294912, 819200, 884736, 160563219machine # 20machine # Allocating group tables: 0/64 done21machine # Writing inode tables: 0/64 done22machine # Creating journal (16384 blocks): done23machine # Writing superblocks and filesystem accounting information: 0/64 done24machine # 25machine # Virtualisation disk image created.26machine # Starting virtiofs daemons...27machine # [2026-09-18T13:10:16Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)28machine # [2026-09-18T13:10:16Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether29machine # [2026-09-18T13:10:16Z INFO virtiofsd] Waiting for vhost-user socket connection...30machine # [2026-09-18T13:10:16Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)31machine # [2026-09-18T13:10:16Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether32machine # [2026-09-18T13:10:16Z INFO virtiofsd] Waiting for vhost-user socket connection...33machine # [2026-09-18T13:10:16Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)34machine # [2026-09-18T13:10:16Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether35machine # [2026-09-18T13:10:16Z INFO virtiofsd] Waiting for vhost-user socket connection...36machine # [2026-09-18T13:10:16Z INFO virtiofsd] Client connected, servicing requests37machine # [2026-09-18T13:10:16Z INFO virtiofsd] Client connected, servicing requests38machine # [2026-09-18T13:10:16Z INFO virtiofsd] Client connected, servicing requests39machine # [ 0.000000] Booting Linux on physical CPU 0x0000000000 [0xc00fac40]40machine # [ 0.000000] Linux version 6.18.51 (nixbld@localhost) (gcc (GCC) 15.3.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT Fri Sep 11 09:49:46 UTC 202641machine # [ 0.000000] KASLR enabled42machine # [ 0.000000] random: crng init done43machine # [ 0.000000] Machine model: linux,dummy-virt44machine # [ 0.000000] efi: UEFI not found.45machine # [ 0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT46machine # [ 0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000ffffffff]47machine # [ 0.000000] NODE_DATA(0) allocated [mem 0xffdec0c0-0xffdef83f]48machine # [ 0.000000] Zone ranges:49machine # [ 0.000000] DMA [mem 0x0000000040000000-0x00000000ffffffff]50machine # [ 0.000000] DMA32 empty51machine # [ 0.000000] Normal empty52machine # [ 0.000000] Device empty53machine # [ 0.000000] Movable zone start for each node54machine # [ 0.000000] Early memory node ranges55machine # [ 0.000000] node 0: [mem 0x0000000040000000-0x00000000ffffffff]56machine # [ 0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000ffffffff]57machine # [ 0.000000] cma: Reserved 32 MiB at 0x00000000fac0000058machine # [ 0.000000] psci: probing for conduit method from DT.59machine # [ 0.000000] psci: PSCIv1.3 detected in firmware.60machine # [ 0.000000] psci: Using standard PSCI v0.2 function IDs61machine # [ 0.000000] psci: Trusted OS migration not required62machine # [ 0.000000] psci: SMC Calling Convention v1.163machine # [ 0.000000] smccc: KVM: hypervisor services detected (0x00000000 0x00000000 0x00000000 0x00000003)64machine # [ 0.000000] percpu: Embedded 76 pages/cpu s186648 r8192 d116456 u31129665machine # [ 0.000000] Detected PIPT I-cache on CPU066machine # [ 0.000000] CPU features: detected: Address authentication (architected QARMA5 algorithm)67machine # [ 0.000000] CPU features: detected: GICv3 CPU interface68machine # [ 0.000000] CPU features: detected: Spectre-v469machine # [ 0.000000] CPU features: detected: Spectre-BHB70machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC03_CPU_3871machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC04_CPU_2372machine # [ 0.000000] alternatives: applying boot alternatives73machine # [ 0.000000] Kernel command line: console=ttyAMA0 console=tty0 panic=1 boot.panic_on_fail clocksource=acpi_pm root=fstab loglevel=7 net.ifnames=0 lsm=landlock,yama,bpf init=/nix/store/1z3zg5nghikmsnibww3mpm672m2j6rhm-nixos-system-machine-test/init regInfo=/nix/store/4ks8ivnqznb4rnnx0b2c2lqrvnz4a0dd-closure-info/registration console=ttyAMA0,115200n8 console=tty074machine # [ 0.000000] Unknown kernel command line parameters "regInfo=/nix/store/4ks8ivnqznb4rnnx0b2c2lqrvnz4a0dd-closure-info/registration", will be passed to user space.75machine # [ 0.000000] printk: log buffer data + meta data: 131072 + 458752 = 589824 bytes76machine # [ 0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)77machine # [ 0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)78machine # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size adjusted to 3MB79machine # [ 0.000000] software IO TLB: area num 2.80machine # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size roundup to 4MB81machine # [ 0.000000] software IO TLB: mapped [mem 0x00000000fa200000-0x00000000fa600000] (4MB)82machine # [ 0.000000] Fallback order for Node 0: 083machine # [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 78643284machine # [ 0.000000] Policy zone: DMA85machine # [ 0.000000] mem auto-init: stack:all(zero), heap alloc:on, heap free:off86machine # [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=187machine # [ 0.000000] allocated 6291456 bytes of page_ext88machine # [ 0.000000] ftrace: allocating 74894 entries in 294 pages89machine # [ 0.000000] ftrace: allocated 294 pages with 4 groups90machine # [ 0.000000] rcu: Hierarchical RCU implementation.91machine # [ 0.000000] rcu: RCU event tracing is enabled.92machine # [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=2.93machine # [ 0.000000] Trampoline variant of Tasks RCU enabled.94machine # [ 0.000000] Rude variant of Tasks RCU enabled.95machine # [ 0.000000] Tracing variant of Tasks RCU enabled.96machine # [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.97machine # [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=298machine # [ 0.000000] RCU Tasks: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.99machine # [ 0.000000] RCU Tasks Rude: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.100machine # [ 0.000000] RCU Tasks Trace: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.101machine # [ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0102machine # [ 0.000000] GICv3: 256 SPIs implemented103machine # [ 0.000000] GICv3: 0 Extended SPIs implemented104machine # [ 0.000000] Root IRQ handler: gic_handle_irq105machine # [ 0.000000] GICv3: GICv3 features: 16 PPIs, DirectLPI106machine # [ 0.000000] GICv3: GICD_CTLR.DS=1, SCR_EL3.FIQ=0107machine # [ 0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a0000108machine # [ 0.000000] ITS [mem 0x08080000-0x0809ffff]109machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Devices @45100000 (indirect, esz 8, psz 64K, shr 1)110machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @45110000 (flat, esz 8, psz 64K, shr 1)111machine # [ 0.000000] GICv3: using LPI property table @0x0000000045120000112machine # [ 0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000045130000113machine # [ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.114machine # [ 0.000000] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns115machine # [ 0.000000] arch_timer: cp15 timer running at 1000.00MHz (virt).116machine # [ 0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns117machine # [ 0.000000] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns118machine # [ 0.000031] arm-pv: using stolen time PV119machine # [ 0.000395] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)120machine # [ 0.000595] Console: colour dummy device 80x25121machine # [ 0.000603] printk: legacy console [tty0] enabled122machine # [ 0.000797] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000)123machine # [ 0.000805] pid_max: default: 32768 minimum: 301124machine # [ 0.000876] LSM: initializing lsm=capability,landlock,yama,bpf,ima125machine # [ 0.001012] landlock: Up and running.126machine # [ 0.001015] Yama: becoming mindful.127machine # [ 0.001468] LSM support for eBPF active128machine # [ 0.001667] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)129machine # [ 0.001730] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)130machine # [ 0.002986] cacheinfo: Unable to detect cache hierarchy for CPU 0131machine # [ 0.003783] rcu: Hierarchical SRCU implementation.132machine # [ 0.003787] rcu: Max phase no-delay instances is 1000.133machine # [ 0.003941] Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level134machine # [ 0.005346] fsl-mc MSI: its@8080000 domain created135machine # [ 0.005440] EFI services will not be available.136machine # [ 0.005565] smp: Bringing up secondary CPUs ...137machine # [ 0.006295] Detected PIPT I-cache on CPU1138machine # [ 0.006405] GICv3: CPU1: found redistributor 1 region 0:0x00000000080c0000139machine # [ 0.006541] GICv3: CPU1: using allocated LPI pending table @0x0000000045140000140machine # [ 0.006676] CPU1: Booted secondary processor 0x0000000001 [0xc00fac40]141machine # [ 0.007328] smp: Brought up 1 node, 2 CPUs142machine # [ 0.007342] SMP: Total of 2 processors activated.143machine # [ 0.007345] CPU: All CPU(s) started at EL1144machine # [ 0.007354] CPU features: detected: Branch Target Identification145machine # [ 0.007358] CPU features: detected: ARMv8.4 Translation Table Level146machine # [ 0.007361] CPU features: detected: Instruction cache invalidation not required for I/D coherence147machine # [ 0.007365] CPU features: detected: Data cache clean to the PoU not required for I/D coherence148machine # [ 0.007368] CPU features: detected: Common not Private translations149machine # [ 0.007371] CPU features: detected: CRC32 instructions150machine # [ 0.007373] CPU features: detected: Data cache clean to Point of Deep Persistence151machine # [ 0.007377] CPU features: detected: Data cache clean to Point of Persistence152machine # [ 0.007380] CPU features: detected: Data independent timing control (DIT)153machine # [ 0.007382] CPU features: detected: E0PD154machine # [ 0.007385] CPU features: detected: Enhanced Counter Virtualization155machine # [ 0.007387] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF)156machine # [ 0.007390] CPU features: detected: Enhanced Virtualization Traps157machine # [ 0.007393] CPU features: detected: Fine Grained Traps158machine # [ 0.007396] CPU features: detected: Generic authentication (architected QARMA5 algorithm)159machine # [ 0.007400] CPU features: detected: RCpc load-acquire (LDAPR)160machine # [ 0.007402] CPU features: detected: LSE atomic instructions161machine # [ 0.007405] CPU features: detected: Privileged Access Never162machine # [ 0.007407] CPU features: detected: PMUv3163machine # [ 0.007410] CPU features: detected: RAS Extension Support164machine # [ 0.007412] CPU features: detected: RASv1p1 Extension Support165machine # [ 0.007415] CPU features: detected: Random Number Generator166machine # [ 0.007417] CPU features: detected: Speculation barrier (SB)167machine # [ 0.007419] CPU features: detected: Stage-2 Force Write-Back168machine # [ 0.007422] CPU features: detected: TLB range maintenance instructions169machine # [ 0.007425] CPU features: detected: Speculative Store Bypassing Safe (SSBS)170machine # [ 0.007534] alternatives: applying system-wide alternatives171machine # [ 0.010581] CPU features: detected: BBM Level 2 without TLB conflict abort172machine # [ 0.010860] Memory: 2944528K/3145728K available (24448K kernel code, 7090K rwdata, 26360K rodata, 4736K init, 1107K bss, 154556K reserved, 32768K cma-reserved)173machine # [ 0.012392] devtmpfs: initialized174machine # [ 0.014998] posixtimers hash table entries: 1024 (order: 2, 16384 bytes, linear)175machine # [ 0.015044] futex hash table entries: 512 (32768 bytes on 1 NUMA nodes, total 32 KiB, linear).176machine # [ 0.015272] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL177machine # [ 0.015278] 0 pages in range for non-PLT usage178machine # [ 0.015279] 508288 pages in range for PLT usage179machine # [ 0.015417] pinctrl core: initialized pinctrl subsystem180machine # [ 0.016275] DMI not present or invalid.181machine # [ 0.019626] NET: Registered PF_NETLINK/PF_ROUTE protocol family182machine # [ 0.022243] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations183machine # [ 0.022566] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations184machine # [ 0.022947] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations185machine # [ 0.022976] audit: initializing netlink subsys (disabled)186machine # [ 0.023814] audit: type=2000 audit(0.020:1): state=initialized audit_enabled=0 res=1187machine # [ 0.026154] thermal_sys: Registered thermal governor 'fair_share'188machine # [ 0.026163] thermal_sys: Registered thermal governor 'bang_bang'189machine # [ 0.026177] thermal_sys: Registered thermal governor 'step_wise'190machine # [ 0.026185] thermal_sys: Registered thermal governor 'user_space'191machine # [ 0.026193] thermal_sys: Registered thermal governor 'power_allocator'192machine # [ 0.026339] cpuidle: using governor ladder193machine # [ 0.026395] cpuidle: using governor menu194machine # [ 0.027329] hw-breakpoint: found 16 breakpoint and 4 watchpoint registers.195machine # [ 0.027413] ASID allocator initialised with 65536 entries196machine # [ 0.031078] Serial: AMBA PL011 UART driver197machine # [ 0.047720] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 13, base_baud = 0) is a PL011 rev1198machine # [ 0.048137] printk: console [ttyAMA0] enabled199machine # [ 0.075603] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages200machine # [ 0.075616] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page201machine # [ 0.075620] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages202machine # [ 0.075624] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page203machine # [ 0.075627] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages204machine # [ 0.075631] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page205machine # [ 0.075634] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages206machine # [ 0.075637] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page207machine # [ 0.084658] fbcon: Taking over console208machine # [ 0.084672] ACPI: Interpreter disabled.209machine # [ 0.087103] iommu: Default domain type: Translated210machine # [ 0.087111] iommu: DMA domain TLB invalidation policy: strict mode211machine # [ 0.090315] SCSI subsystem initialized212machine # [ 0.090643] usbcore: registered new interface driver usbfs213machine # [ 0.090683] usbcore: registered new interface driver hub214machine # [ 0.090707] usbcore: registered new device driver usb215machine # [ 0.091046] pps_core: LinuxPPS API ver. 1 registered216machine # [ 0.091050] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>217machine # [ 0.091060] PTP clock support registered218machine # [ 0.091123] EDAC MC: Ver: 3.0.0219machine # [ 0.091355] scmi_core: SCMI protocol bus registered220machine # [ 0.091979] FPGA manager framework221machine # [ 0.092794] vgaarb: loaded222machine # [ 0.095507] clocksource: Switched to clocksource arch_sys_counter223machine # [ 0.096256] VFS: Disk quotas dquot_6.6.0224machine # [ 0.096285] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)225machine # [ 0.099098] netfs: FS-Cache loaded226machine # [ 0.099296] pnp: PnP ACPI: disabled227machine # [ 0.103333] NET: Registered PF_INET protocol family228machine # [ 0.103947] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)229machine # [ 0.136144] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)230machine # [ 0.136195] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)231machine # [ 0.136232] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)232machine # [ 0.136368] TCP bind hash table entries: 32768 (order: 8, 1048576 bytes, linear)233machine # [ 0.136660] TCP: Hash tables configured (established 32768 bind 32768)234machine # [ 0.136775] MPTCP token hash table entries: 4096 (order: 5, 98304 bytes, linear)235machine # [ 0.136819] UDP hash table entries: 2048 (order: 5, 131072 bytes, linear)236machine # [ 0.136883] UDP-Lite hash table entries: 2048 (order: 5, 131072 bytes, linear)237machine # [ 0.137047] NET: Registered PF_UNIX/PF_LOCAL protocol family238machine # [ 0.137071] NET: Registered PF_XDP protocol family239machine # [ 0.137088] PCI: CLS 0 bytes, default 64240machine # [ 0.137385] Trying to unpack rootfs image as initramfs...241machine # [ 0.147599] kvm [1]: HYP mode not available242machine # [ 0.244197] Initialise system trusted keyrings243machine # [ 0.247759] workingset: timestamp_bits=42 max_order=20 bucket_order=0244machine # [ 0.252049] squashfs: version 4.0 (2009/01/31) Phillip Lougher245machine # [ 0.252979] 9p: Installing v9fs 9p2000 file system support246machine # [ 0.267983] Key type asymmetric registered247machine # [ 0.267994] Asymmetric key parser 'x509' registered248machine # [ 0.268092] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 242)249machine # [ 0.271598] io scheduler mq-deadline registered250machine # [ 0.271615] io scheduler kyber registered251machine # [ 0.280949] pl061_gpio 9030000.pl061: PL061 GPIO chip registered252machine # [ 0.283599] ledtrig-cpu: registered to indicate activity on CPUs253machine # [ 0.284151] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:254machine # [ 0.284173] pci-host-generic 4010000000.pcie: IO 0x003eff0000..0x003effffff -> 0x0000000000255machine # [ 0.284189] pci-host-generic 4010000000.pcie: MEM 0x0010000000..0x003efeffff -> 0x0010000000256machine # [ 0.284200] pci-host-generic 4010000000.pcie: MEM 0x8000000000..0xffffffffff -> 0x8000000000257machine # [ 0.284246] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits258machine # [ 0.284273] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]259machine # [ 0.284365] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00260machine # [ 0.284378] pci_bus 0000:00: root bus resource [bus 00-ff]261machine # [ 0.284386] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]262machine # [ 0.284393] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]263machine # [ 0.284399] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]264machine # [ 0.284511] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint265machine # [ 0.285101] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint266machine # [ 0.285353] pci 0000:00:01.0: BAR 0 [io 0x0000-0x001f]267machine # [ 0.285375] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff]268machine # [ 0.285415] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]269machine # [ 0.285437] pci 0000:00:01.0: ROM [mem 0x00000000-0x0003ffff pref]270machine # [ 0.286058] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint271machine # [ 0.286303] pci 0000:00:02.0: BAR 0 [io 0x0000-0x001f]272machine # [ 0.286324] pci 0000:00:02.0: BAR 1 [mem 0x00000000-0x00000fff]273machine # [ 0.286364] pci 0000:00:02.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]274machine # [ 0.286969] pci 0000:00:03.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint275machine # [ 0.287224] pci 0000:00:03.0: BAR 0 [io 0x0000-0x007f]276machine # [ 0.287249] pci 0000:00:03.0: BAR 1 [mem 0x00000000-0x00000fff]277machine # [ 0.287288] pci 0000:00:03.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]278machine # [ 0.316751] pci 0000:00:04.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint279machine # [ 0.316969] pci 0000:00:04.0: BAR 0 [io 0x0000-0x001f]280machine # [ 0.316987] pci 0000:00:04.0: BAR 1 [mem 0x00000000-0x00000fff]281machine # [ 0.317023] pci 0000:00:04.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]282machine # [ 0.317041] pci 0000:00:04.0: ROM [mem 0x00000000-0x0003ffff pref]283machine # [ 0.317594] pci 0000:00:05.0: [1af4:1050] type 00 class 0x038000 conventional PCI endpoint284machine # [ 0.317816] pci 0000:00:05.0: BAR 1 [mem 0x00000000-0x00000fff]285machine # [ 0.317851] pci 0000:00:05.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]286machine # [ 0.318375] pci 0000:00:06.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint287machine # [ 0.318595] pci 0000:00:06.0: BAR 1 [mem 0x00000000-0x00000fff]288machine # [ 0.318630] pci 0000:00:06.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]289machine # [ 0.319082] pci 0000:00:07.0: [8086:24cd] type 00 class 0x0c0320 conventional PCI endpoint290machine # [ 0.319303] pci 0000:00:07.0: BAR 0 [mem 0x00000000-0x00000fff]291machine # [ 0.331451] pci 0000:00:08.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint292machine # [ 0.332711] pci 0000:00:08.0: BAR 1 [mem 0x00000000-0x00000fff]293machine # [ 0.332746] pci 0000:00:08.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]294machine # [ 0.333214] pci 0000:00:09.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint295machine # [ 0.333408] pci 0000:00:09.0: BAR 1 [mem 0x00000000-0x00000fff]296machine # [ 0.333439] pci 0000:00:09.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]297machine # [ 0.333904] pci 0000:00:0a.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint298machine # [ 0.334096] pci 0000:00:0a.0: BAR 1 [mem 0x00000000-0x00000fff]299machine # [ 0.334127] pci 0000:00:0a.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]300machine # [ 0.334595] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint301machine # [ 0.334881] pci 0000:00:0b.0: BAR 0 [io 0x0000-0x003f]302machine # [ 0.334900] pci 0000:00:0b.0: BAR 1 [mem 0x00000000-0x00000fff]303machine # [ 0.334930] pci 0000:00:0b.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]304machine # [ 0.335398] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint305machine # [ 0.346736] pci 0000:00:0c.0: BAR 0 [io 0x0000-0x001f]306machine # [ 0.346757] pci 0000:00:0c.0: BAR 1 [mem 0x00000000-0x00000fff]307machine # [ 0.346787] pci 0000:00:0c.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]308machine # [ 0.347409] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned309machine # [ 0.347421] pci 0000:00:04.0: ROM [mem 0x10040000-0x1007ffff pref]: assigned310machine # [ 0.347427] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned311machine # [ 0.347471] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned312machine # [ 0.353637] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned313machine # [ 0.353691] pci 0000:00:04.0: BAR 4 [mem 0x800000c000-0x800000ffff 64bit pref]: assigned314machine # [ 0.353739] pci 0000:00:05.0: BAR 4 [mem 0x8000010000-0x8000013fff 64bit pref]: assigned315machine # [ 0.353787] pci 0000:00:06.0: BAR 4 [mem 0x8000014000-0x8000017fff 64bit pref]: assigned316machine # [ 0.353834] pci 0000:00:08.0: BAR 4 [mem 0x8000018000-0x800001bfff 64bit pref]: assigned317machine # [ 0.353882] pci 0000:00:09.0: BAR 4 [mem 0x800001c000-0x800001ffff 64bit pref]: assigned318machine # [ 0.353929] pci 0000:00:0a.0: BAR 4 [mem 0x8000020000-0x8000023fff 64bit pref]: assigned319machine # [ 0.353976] pci 0000:00:0b.0: BAR 4 [mem 0x8000024000-0x8000027fff 64bit pref]: assigned320machine # [ 0.354052] pci 0000:00:0c.0: BAR 4 [mem 0x8000028000-0x800002bfff 64bit pref]: assigned321machine # [ 0.354099] pci 0000:00:01.0: BAR 1 [mem 0x10080000-0x10080fff]: assigned322machine # [ 0.354121] pci 0000:00:02.0: BAR 1 [mem 0x10081000-0x10081fff]: assigned323machine # [ 0.354148] pci 0000:00:03.0: BAR 1 [mem 0x10082000-0x10082fff]: assigned324machine # [ 0.354170] pci 0000:00:04.0: BAR 1 [mem 0x10083000-0x10083fff]: assigned325machine # [ 0.354192] pci 0000:00:05.0: BAR 1 [mem 0x10084000-0x10084fff]: assigned326machine # [ 0.354214] pci 0000:00:06.0: BAR 1 [mem 0x10085000-0x10085fff]: assigned327machine # [ 0.354237] pci 0000:00:07.0: BAR 0 [mem 0x10086000-0x10086fff]: assigned328machine # [ 0.354260] pci 0000:00:08.0: BAR 1 [mem 0x10087000-0x10087fff]: assigned329machine # [ 0.354283] pci 0000:00:09.0: BAR 1 [mem 0x10088000-0x10088fff]: assigned330machine # [ 0.354306] pci 0000:00:0a.0: BAR 1 [mem 0x10089000-0x10089fff]: assigned331machine # [ 0.354328] pci 0000:00:0b.0: BAR 1 [mem 0x1008a000-0x1008afff]: assigned332machine # [ 0.354351] pci 0000:00:0c.0: BAR 1 [mem 0x1008b000-0x1008bfff]: assigned333machine # [ 0.354373] pci 0000:00:03.0: BAR 0 [io 0x1000-0x107f]: assigned334machine # [ 0.354395] pci 0000:00:0b.0: BAR 0 [io 0x1080-0x10bf]: assigned335machine # [ 0.354417] pci 0000:00:01.0: BAR 0 [io 0x10c0-0x10df]: assigned336machine # [ 0.354439] pci 0000:00:02.0: BAR 0 [io 0x10e0-0x10ff]: assigned337machine # [ 0.354460] pci 0000:00:04.0: BAR 0 [io 0x1100-0x111f]: assigned338machine # [ 0.354482] pci 0000:00:0c.0: BAR 0 [io 0x1120-0x113f]: assigned339machine # [ 0.354509] pci_bus 0000:00: resource 4 [io 0x0000-0xffff]340machine # [ 0.354518] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]341machine # [ 0.354523] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]342machine # [ 0.355356] pci 0000:00:07.0: enabling device (0000 -> 0002)343machine # [ 0.383212] pci 0000:00:07.0: quirk_usb_early_handoff+0x0/0xa60 took 27208 usecs344machine # [ 0.397978] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)345machine # [ 0.401285] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)346machine # [ 0.404420] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)347machine # [ 0.406664] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)348machine # [ 0.413083] virtio-pci 0000:00:05.0: enabling device (0000 -> 0002)349machine # [ 0.415379] virtio-pci 0000:00:06.0: enabling device (0000 -> 0002)350machine # [ 0.418921] virtio-pci 0000:00:08.0: enabling device (0000 -> 0002)351machine # [ 0.422038] virtio-pci 0000:00:09.0: enabling device (0000 -> 0002)352machine # [ 0.426299] virtio-pci 0000:00:0a.0: enabling device (0000 -> 0002)353machine # [ 0.430118] virtio-pci 0000:00:0b.0: enabling device (0000 -> 0003)354machine # [ 0.433496] virtio-pci 0000:00:0c.0: enabling device (0000 -> 0003)355machine # [ 0.439645] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled356machine # [ 0.442418] msm_serial: driver initialized357machine # [ 0.442591] SuperH (H)SCI(F) driver initialized358machine # [ 0.442648] STM32 USART driver initialized359machine # [ 0.462766] loop: module loaded360machine # [ 0.463045] virtio_blk virtio2: 2/0/0 default/read/poll queues361machine # [ 0.465406] virtio_blk virtio2: [vda] 16777216 512-byte logical blocks (8.59 GB/8.00 GiB)362machine # [ 0.468863] megasas: 07.734.00.00-rc1363machine # [ 0.469872] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]364machine # [ 0.474395] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000365machine # [ 0.474494] Intel/Sharp Extended Query Table at 0x0031366machine # [ 0.478065] Using buffer write method367machine # [ 0.478165] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]368machine # [ 0.482418] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000369machine # [ 0.482468] Intel/Sharp Extended Query Table at 0x0031370machine # [ 0.485870] Using buffer write method371machine # [ 0.485917] Concatenating MTD devices:372machine # [ 0.485922] (0): "0.flash"373machine # [ 0.485926] (1): "0.flash"374machine # [ 0.485930] into device "0.flash"375machine # [ 0.599177] Freeing initrd memory: 26900K376machine # [ 0.606309] tun: Universal TUN/TAP device driver, 1.6377machine # [ 0.610667] thunder_xcv, ver 1.0378machine # [ 0.610723] thunder_bgx, ver 1.0379machine # [ 0.610750] nicpf, ver 1.0380machine # [ 0.611350] e1000: Intel(R) PRO/1000 Network Driver381machine # [ 0.611354] e1000: Copyright (c) 1999-2006 Intel Corporation.382machine # [ 0.611378] e1000e: Intel(R) PRO/1000 Network Driver383machine # [ 0.611384] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.384machine # [ 0.611412] igb: Intel(R) Gigabit Ethernet Network Driver385machine # [ 0.611415] igb: Copyright (c) 2007-2014 Intel Corporation.386machine # [ 0.611440] igbvf: Intel(R) Gigabit Virtual Function Network Driver387machine # [ 0.611444] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.388machine # [ 0.611645] sky2: driver version 1.30389machine # [ 0.613313] usbcore: registered new interface driver usb-storage390machine # [ 0.613457] usbcore: registered new interface driver usbserial_generic391machine # [ 0.613474] usbserial: USB Serial support registered for generic392machine # [ 0.614104] hv_vmbus: registering driver hyperv_keyboard393machine # [ 0.615133] rtc-pl031 9010000.pl031: registered as rtc0394machine # [ 0.615232] rtc-pl031 9010000.pl031: setting system clock to 2026-09-18T13:10:18 UTC (1789737018)395machine # [ 0.615642] i2c_dev: i2c /dev entries driver396machine # [ 0.617647] ehci-pci 0000:00:07.0: EHCI Host Controller397machine # [ 0.617745] ehci-pci 0000:00:07.0: new USB bus registered, assigned bus number 1398machine # [ 0.618570] ehci-pci 0000:00:07.0: irq 16, io mem 0x10086000399machine # [ 0.618949] sdhci: Secure Digital Host Controller Interface driver400machine # [ 0.618957] sdhci: Copyright(c) Pierre Ossman401machine # [ 0.619249] Synopsys Designware Multimedia Card Interface Driver402machine # [ 0.619662] sdhci-pltfm: SDHCI platform and OF driver helper403machine # [ 0.621291] hid: raw HID events driver (C) Jiri Kosina404machine # [ 0.621582] usbcore: registered new interface driver usbhid405machine # [ 0.621586] usbhid: USB HID core driver406machine # [ 0.629368] ehci-pci 0000:00:07.0: USB 2.0 started, EHCI 1.00407machine # [ 0.629544] hw perfevents: enabled with armv8_pmuv3 PMU driver, 11 (0,800003ff) counters available408machine # [ 0.631177] drop_monitor: Initializing network drop monitor service409machine # [ 0.631344] NET: Registered PF_INET6 protocol family410machine # [ 0.631913] Segment Routing with IPv6411machine # [ 0.631927] In-situ OAM (IOAM) with IPv6412machine # [ 0.631952] NET: Registered PF_PACKET protocol family413machine # [ 0.632041] 9pnet: Installing 9P2000 support414machine # [ 0.632084] Key type dns_resolver registered415machine # [ 0.637673] hub 1-0:1.0: USB hub found416machine # [ 0.637690] hub 1-0:1.0: 6 ports detected417machine # [ 0.638282] registered taskstats version 1418machine # [ 0.638425] Loading compiled-in X.509 certificates419machine # [ 0.646574] Demotion targets for Node 0: null420machine # [ 0.646742] Key type .fscrypt registered421machine # [ 0.646746] Key type fscrypt-provisioning registered422machine # [ 0.646849] ima: No TPM chip found, activating TPM-bypass!423machine # [ 0.646867] ima: Allocated hash algorithm: sha1424machine # [ 0.646888] ima: No architecture policies found425machine # [ 0.647671] input: gpio-keys as /devices/platform/gpio-keys/input/input0426machine # [ 0.665816] clk: Disabling unused clocks427machine # [ 0.665834] PM: genpd: Disabling unused power domains428machine # [ 0.669885] Freeing unused kernel memory: 4736K429machine # [ 0.670094] Run /init as init process430machine # [ 0.708217] systemd[1]: Successfully made /usr/ read-only.431machine # [ 0.883594] usb 1-1: new high-speed USB device number 2 using ehci-pci432machine # [ 1.036208] input: QEMU QEMU USB Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:07.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input1433machine # [ 1.042343] 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)434machine # [ 1.042406] systemd[1]: Detected virtualization qemu.435machine # [ 1.042480] systemd[1]: Detected architecture arm64.436machine # [ 1.042495] systemd[1]: Running in initrd.437machine # [ 1.043464] systemd[1]: Initializing machine ID from random generator.438machine # [ 1.043833] systemd[1]: Hostname set to <machine>.439machine # [ 1.127935] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:07.0-1/input0440machine # [ 1.247580] usb 1-2: new high-speed USB device number 3 using ehci-pci441machine # [ 1.272660] systemd[1]: bpf-restrict-fs: LSM BPF program attached442machine # [ 1.364023] systemd[1]: Queued start job for default target Initrd Default Target.443machine # [ 1.384309] systemd[1]: Created slice Slice /system/modprobe.444machine # [ 1.384647] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.445machine # [ 1.384695] systemd[1]: Expecting device /dev/disk/by-label/nixos...446machine # [ 1.384728] systemd[1]: Reached target Path Units.447machine # [ 1.384751] systemd[1]: Reached target Slice Units.448machine # [ 1.384776] systemd[1]: Reached target Swaps.449machine # [ 1.384801] systemd[1]: Reached target Timer Units.450machine # [ 1.385088] systemd[1]: Listening on D-Bus System Message Bus Socket.451machine # [ 1.385312] systemd[1]: Listening on Journal Socket (/dev/log).452machine # [ 1.385612] systemd[1]: Listening on Journal Sockets.453machine # [ 1.385811] systemd[1]: Listening on udev Control Socket.454machine # [ 1.385931] systemd[1]: Listening on udev Kernel Socket.455machine # [ 1.385966] systemd[1]: Reached target Socket Units.456machine # [ 1.388608] systemd[1]: Starting Create List of Static Device Nodes...457machine # [ 1.388715] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs458machine # [ 1.393215] systemd[1]: Mounting Kernel Configuration File System...459machine # [ 1.409750] input: QEMU QEMU USB Tablet as /devices/platform/4010000000.pcie/pci0000:00/0000:00:07.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input2460machine # [ 1.410101] hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:07.0-2/input0461machine # [ 1.428062] systemd[1]: Starting Journal Service...462machine # [ 1.439874] systemd[1]: Starting Load Kernel Modules...463machine # [ 1.440071] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os464machine # [ 1.442111] systemd[1]: Starting Coldplug All udev Devices...465machine # [ 1.448393] systemd[1]: Finished Create List of Static Device Nodes.466machine # [ 1.458326] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...467machine # [ 1.519765] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.468machine # [ 1.520367] systemd[1]: Mounted Kernel Configuration File System.469machine # [ 1.522079] systemd[1]: Starting Create Static Device Nodes in /dev...470machine # [ 1.538898] systemd-journald[80]: Collecting audit messages is disabled.471machine # [ 1.553154] [drm] pci: virtio-gpu-pci detected at 0000:00:05.0472machine # [ 1.553577] [drm] features: -virgl +edid -resource_blob -host_visible473machine # [ 1.553595] [drm] features: -context_init474machine # [ 1.559758] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.475machine # [ 1.565181] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev476machine # [ 1.567617] [drm] number of scanouts: 1477machine # [ 1.567633] [drm] number of cap sets: 0478machine # [ 1.568217] virtio-pci 0000:00:05.0: [drm] Registered 1 planes with drm panic479machine # [ 1.568225] [drm] Initialized virtio_gpu 0.1.0 for 0000:00:05.0 on minor 0480machine # [ 1.584445] Console: switching to colour frame buffer device 160x50481machine # [ 1.591013] virtio-pci 0000:00:05.0: [drm] fb0: virtio_gpudrmfb frame buffer device482machine # [ 1.591553] systemd[1]: Finished Create Static Device Nodes in /dev.483machine # [ 1.591778] systemd[1]: Reached target Preparation for Local File Systems.484machine # [ 1.591808] systemd[1]: Reached target Local File Systems.485machine # [ 1.600801] systemd[1]: Starting Rule-based Manager for Device Events and Files...486machine # [ 1.608138] systemd[1]: Finished Load Kernel Modules.487machine # [ 1.615884] systemd[1]: Starting Apply Kernel Variables...488machine # [ 1.645492] systemd[1]: Started Journal Service.489machine # [ 1.643905] systemd-modules-load[81]: Using 2 probe threads490machine # [ 1.652453] systemd-modules-load[81]: Module 'virtio_balloon' is built in491machine # [ 1.653595] systemd-modules-load[81]: Module 'virtio_console' is built in492machine # [ 1.654694] systemd-modules-load[81]: Inserted module 'dm_mod'493machine # [ 1.655626] systemd-modules-load[81]: Module 'virtio_rng' is built in494machine # [ 1.664563] systemd-modules-load[81]: Inserted module 'virtio_gpu'495machine # [ 1.667358] systemd[1]: Starting Create System Files and Directories...496machine # [ 1.674187] systemd-udevd[88]: Using default interface naming scheme 'v261'.497machine # [ 1.675405] systemd[1]: Finished Apply Kernel Variables.498machine # [ 1.688213] systemd[1]: Started Rule-based Manager for Device Events and Files.499machine # [ 1.701715] systemd[1]: Finished Create System Files and Directories.500machine # [ 1.745240] systemd[1]: Starting Virtual Console Setup...501machine # [ 1.776780] systemd-vconsole-setup[112]: Configuration of first virtual console was skipped, ignoring remaining ones.502machine # [ 1.780385] systemd[1]: Finished Virtual Console Setup.503machine # [ 2.186663] systemd[1]: Finished Coldplug All udev Devices.504machine # [ 2.187643] systemd[1]: Reached target System Initialization.505machine # [ 2.188827] systemd[1]: Reached target Basic System.506machine # [ 2.361018] (udev-worker)[122]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.507machine # [ 2.365591] (udev-worker)[122]: Network interface NamePolicy= disabled on kernel command line.508machine # [ 2.408128] (udev-worker)[107]: Network interface NamePolicy= disabled on kernel command line.509machine # [ 2.433370] systemd[1]: Found device /dev/disk/by-label/nixos.510machine # [ 2.444122] systemd[1]: Reached target Initrd Root Device.511machine # [ 2.445605] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos...512machine # [ 2.483880] systemd-fsck[130]: nixos: clean, 12/524288 files, 58513/2097152 blocks513machine # [ 2.490159] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos.514machine # [ 2.496283] systemd[1]: Mounting /sysroot...515machine # [ 2.523941] EXT4-fs (vda): mounted filesystem 18634b26-91c0-4be2-beef-b30608c30f9c r/w with ordered data mode. Quota mode: none.516machine # [ 2.522966] systemd[1]: Mounted /sysroot.517machine # [ 2.524213] systemd[1]: Reached target Initrd Root File System.518machine # [ 2.528197] systemd[1]: Starting Mountpoints Configured in the Real Root...519machine # [ 2.565015] systemd-sysroot-fstab-check[138]: /sysroot should be mounted in the initrd, will request daemon-reload.520machine # [ 2.571153] systemd[1]: Reload requested from client PID 138 ('systemd-sysroot') (unit initrd-parse-etc.service)...521machine # [ 2.574671] systemd[1]: Reloading...522machine # [ 2.702053] systemd[1]: Reloading finished in 132 ms.523machine # [ 2.748528] systemd-sysroot-fstab-check[138]: Requesting initrd-fs.target/start/replace...524machine # [ 2.751344] systemd-sysroot-fstab-check[138]: Requesting swap.target/start/replace...525machine # [ 2.754332] systemd[1]: initrd-parse-etc.service: Deactivated successfully.526machine # [ 2.757809] systemd[1]: Finished Mountpoints Configured in the Real Root.527machine # [ 2.758852] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies.528machine # [ 3.118402] fuse: init (API version 7.45)529machine # [ 3.162401] (udev-worker)[106]: mtd0ro: Failed to find and pin callout binary "/nix/store/gnadg5slifq2r638xvz4pv6vrsdl9xkj-systemd-261.2/lib/udev/mtd_probe": No such file or directory530machine # [ 3.166222] (udev-worker)[106]: mtd0ro: /etc/udev/rules.d/75-probe_mtd.rules:5 IMPORT{program}="mtd_probe $devnode": Failed to execute "mtd_probe /dev/mtd0ro", ignoring: No such file or directory531machine # [ 3.178729] virtiofs virtio6: discovered new tag: nix-store532machine # [ 3.178540] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.533machine # [ 3.179644] systemd[1]: Stopped Virtual Console Setup.534machine # [ 3.180461] systemd[1]: Stopping Virtual Console Setup...535machine # [ 3.181218] systemd[1]: Starting Virtual Console Setup...536machine # [ 3.185575] virtiofs virtio6: virtio_fs_setup_dax: No cache capability537machine # [ 3.201126] virtiofs virtio7: discovered new tag: shared538machine # [ 3.201969] virtiofs virtio7: virtio_fs_setup_dax: No cache capability539machine # [ 3.206248] virtiofs virtio8: discovered new tag: xchg540machine # [ 3.207117] virtiofs virtio8: virtio_fs_setup_dax: No cache capability541machine # [ 3.222955] systemd-vconsole-setup[158]: Configuration of first virtual console was skipped, ignoring remaining ones.542machine # [ 3.224799] systemd[1]: Finished Virtual Console Setup.543machine # [ 3.447092] systemd[1]: Mounting /sysroot/nix/.ro-store...544machine # [ 3.455740] systemd[1]: Mounting /sysroot/nix/.rw-store...545machine # [ 3.484488] systemd[1]: Mounting /sysroot/run...546machine # [ 3.489736] systemd[1]: Mounting /sysroot/tmp/shared...547machine # [ 3.501871] systemd[1]: Mounting /sysroot/tmp/xchg...548machine # [ 3.525381] systemd[1]: Mounted /sysroot/nix/.ro-store.549machine # [ 3.527763] systemd[1]: Mounted /sysroot/nix/.rw-store.550machine # [ 3.534923] systemd[1]: Starting rw-sysroot-nix-store.service...551machine # [ 3.554958] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.552machine # [ 3.557503] systemd[1]: Finished rw-sysroot-nix-store.service.553machine # [ 3.564620] systemd[1]: Mounted /sysroot/run.554machine # [ 3.567018] systemd[1]: Mounted /sysroot/tmp/xchg.555machine # [ 3.569352] systemd[1]: Mounted /sysroot/tmp/shared.556machine # [ 4.445620] systemd[1]: Mounting /sysroot/nix/store...557machine # [ 4.520772] systemd[1]: Mounted /sysroot/nix/store.558machine # [ 4.523092] systemd[1]: Reached target Initrd File Systems.559machine # [ 4.526655] systemd[1]: Starting Find NixOS closure...560machine # [ 4.532926] systemd[1]: Starting Create Volatile Files and Directories in the Real Root...561machine # [ 4.581873] systemd[1]: Finished Create Volatile Files and Directories in the Real Root.562machine # [ 4.587887] systemd[1]: sysroot-run-credentials-systemd\x2dtmpfiles\x2dsetup\x2dsysroot.service.mount: Deactivated successfully.563machine # [ 4.601022] systemd[1]: Finished Find NixOS closure.564machine # [ 4.603324] systemd[1]: Reached target Initrd Default Target.565machine # [ 4.606001] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...566machine # [ 4.655550] systemd[1]: Stopped target Initrd Default Target.567machine # [ 4.660574] systemd[1]: Stopped target Basic System.568machine # [ 4.662809] systemd[1]: Stopped target Initrd Root Device.569machine # [ 4.665322] systemd[1]: Stopped target Path Units.570machine # [ 4.667433] systemd[1]: systemd-ask-password-console.path: Deactivated successfully.571machine # [ 4.670914] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.572machine # [ 4.674110] systemd[1]: Stopped target Slice Units.573machine # [ 4.676101] systemd[1]: Stopped target Socket Units.574machine # [ 4.677929] systemd[1]: Stopped target System Initialization.575machine # [ 4.680002] systemd[1]: Stopped target Swaps.576machine # [ 4.683304] systemd[1]: Stopped target Timer Units.577machine # [ 4.687585] systemd[1]: dbus.socket: Deactivated successfully.578machine # [ 4.691955] systemd[1]: Closed D-Bus System Message Bus Socket.579machine # [ 4.693714] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully.580machine # [ 4.695939] systemd[1]: Stopped Find NixOS closure.581machine # [ 4.701611] systemd[1]: Starting rw-sysroot-nix-store.service...582machine # [ 4.703183] systemd[1]: systemd-sysctl.service: Deactivated successfully.583machine # [ 4.704999] systemd[1]: Stopped Apply Kernel Variables.584machine # [ 4.706283] systemd[1]: systemd-modules-load.service: Deactivated successfully.585machine # [ 4.707981] systemd[1]: Stopped Load Kernel Modules.586machine # [ 4.710141] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully.587machine # [ 4.711999] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root.588machine # [ 4.714547] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.589machine # [ 4.716256] systemd[1]: Stopped Create System Files and Directories.590machine # [ 4.718208] systemd[1]: Stopped target Local File Systems.591machine # [ 4.722916] systemd[1]: Stopped target Preparation for Local File Systems.592machine # [ 4.724740] systemd[1]: systemd-udev-trigger.service: Deactivated successfully.593machine # [ 4.726362] systemd[1]: Stopped Coldplug All udev Devices.594machine # [ 4.727676] systemd[1]: Stopping Rule-based Manager for Device Events and Files...595machine # [ 4.729747] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.596machine # [ 4.731409] systemd[1]: Stopped Virtual Console Setup.597machine # [ 4.732687] systemd[1]: initrd-cleanup.service: Deactivated successfully.598machine # [ 4.734215] systemd[1]: Finished Cleaning Up and Shutting Down Daemons.599machine # [ 4.735731] systemd[1]: systemd-udevd.service: Deactivated successfully.600machine # [ 4.737409] systemd[1]: Stopped Rule-based Manager for Device Events and Files.601machine # [ 4.739042] systemd[1]: systemd-udevd.service: Consumed 1.811s CPU time over 3.122s wall clock time, 29.7M memory peak.602machine # [ 4.741543] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.603machine # [ 4.743371] systemd[1]: Finished rw-sysroot-nix-store.service.604machine # [ 4.745148] systemd[1]: systemd-udevd-control.socket: Deactivated successfully.605machine # [ 4.746802] systemd[1]: Closed udev Control Socket.606machine # [ 4.747969] systemd[1]: Starting Cleanup udev Database...607machine # [ 4.749198] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.608machine # [ 4.750845] systemd[1]: Stopped Create Static Device Nodes in /dev.609machine # [ 4.752205] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully.610machine # [ 4.753875] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully.611machine # [ 4.755338] systemd[1]: kmod-static-nodes.service: Deactivated successfully.612machine # [ 4.757037] systemd[1]: Stopped Create List of Static Device Nodes.613machine # [ 4.794612] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.614machine # [ 4.797807] systemd[1]: Finished Cleanup udev Database.615machine # [ 4.799746] systemd[1]: Reached target Switch Root.616machine # [ 4.801696] systemd[1]: Starting NixOS Activation...617machine # [ 4.913473] initrd-nixos-activation-start[193]: booting system configuration /nix/store/1z3zg5nghikmsnibww3mpm672m2j6rhm-nixos-system-machine-test618machine # [ 4.958353] initrd-nixos-activation-start[193]: running activation script...619machine # [ 5.366685] initrd-nixos-activation-start[216]: setting up /etc...620machine # [ 5.576925] systemd[1]: initrd-nixos-activation.service: Deactivated successfully.621machine # [ 5.579450] systemd[1]: Finished NixOS Activation.622machine # [ 5.581082] systemd[1]: Starting Switch Root...623machine # [ 5.613912] systemd[1]: Switching root.624machine # [ 5.764797] systemd-journald[80]: Received SIGTERM from PID 1 (systemd).625machine # [ 6.447094] 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)626machine # [ 6.447298] systemd[1]: Detected virtualization qemu.627machine # [ 6.447439] systemd[1]: Detected architecture arm64.628machine # [ 6.448118] systemd[1]: Detected first boot.629machine # [ 6.453169] systemd[1]: Initializing machine ID from random generator.630machine # [ 6.715296] systemd[1]: bpf-restrict-fs: LSM BPF program attached631machine # [ 6.875833] systemd[1]: Applying preset policy.632machine # [ 7.193037] systemd[1]: Populated /etc with preset unit settings.633machine # [ 7.577611] systemd[1]: initrd-switch-root.service: Deactivated successfully.634machine # [ 7.578844] systemd[1]: Stopped initrd-switch-root.service.635machine # [ 7.582131] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.636machine # [ 7.587339] systemd[1]: Created slice Slice /system/getty.637machine # [ 7.589762] systemd[1]: Created slice User and Session Slice.638machine # [ 7.590658] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.639machine # [ 7.592778] systemd[1]: Started Forward Password Requests to Wall Directory Watch.640machine # [ 7.593415] systemd[1]: Expecting device /dev/hvc0...641machine # [ 7.594242] systemd[1]: Expecting device /dev/ttyAMA0...642machine # [ 7.595107] systemd[1]: Reached target Local Encrypted Volumes.643machine # [ 7.595991] systemd[1]: Stopped target initrd-fs.target.644machine # [ 7.596817] systemd[1]: Stopped target initrd-root-fs.target.645machine # [ 7.597631] systemd[1]: Stopped target initrd-switch-root.target.646machine # [ 7.598481] systemd[1]: Reached target Virtual Machines and Containers.647machine # [ 7.599365] systemd[1]: Reached target Path Units.648machine # [ 7.600181] systemd[1]: Reached target Remote File Systems.649machine # [ 7.600998] systemd[1]: Reached target Slice Units.650machine # [ 7.601846] systemd[1]: Reached target Swaps.651machine # [ 7.619232] systemd[1]: Listening on Query the User Interactively for a Password.652machine # [ 7.625115] systemd[1]: Listening on Process Core Dump Socket.653machine # [ 7.629664] systemd[1]: Listening on Credential Encryption/Decryption.654machine # [ 7.634409] systemd[1]: Listening on Factory Reset Management.655machine # [ 7.635464] systemd[1]: Listening on Hostname Service Socket.656machine # [ 7.644209] systemd[1]: Starting Journal Log Access Socket...657machine # [ 7.645977] systemd[1]: Listening on Journal Audit Socket.658machine # [ 7.652063] systemd[1]: Listening on Console Output Muting Service Socket.659machine # [ 7.653156] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.660machine # [ 7.653841] systemd[1]: TPM PCR Measurements skipped, unmet condition check ConditionSecurity=measured-os661machine # [ 7.654391] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki662machine # [ 7.667893] systemd[1]: Listening on Disk Repartitioning Service Socket.663machine # [ 7.669020] systemd[1]: Listening on udev Control Socket.664machine # [ 7.670047] systemd[1]: Listening on udev Varlink Socket.665machine # [ 7.676792] systemd[1]: Mounting Huge Pages File System...666machine # [ 7.682716] systemd[1]: Mounting POSIX Message Queue File System...667machine # [ 7.702733] systemd[1]: Mounting Kernel Debug File System...668machine # [ 7.709483] systemd[1]: Mounting Kernel Trace File System...669machine # [ 7.720627] systemd[1]: Starting Create List of Static Device Nodes...670machine # [ 7.721286] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs671machine # [ 7.739951] systemd[1]: Mounting Kernel Configuration File System...672machine # [ 7.740564] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm673machine # [ 7.741052] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore674machine # [ 7.741607] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse675machine # [ 7.758390] systemd[1]: Mounting FUSE Control File System...676machine # [ 7.759284] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67677machine # [ 7.769366] systemd[1]: Starting Journal Service...678machine # [ 7.784322] systemd[1]: Starting Load Kernel Modules...679machine # [ 7.807420] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...680machine # [ 7.819728] systemd[1]: Starting Remount Root and Kernel File Systems...681machine # [ 7.820889] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os682machine # [ 7.828950] systemd[1]: Starting Coldplug All udev Devices...683machine # [ 7.835455] systemd[1]: Listening on Journal Log Access Socket.684machine # [ 7.840390] systemd[1]: Mounted Huge Pages File System.685machine # [ 7.843917] systemd[1]: Mounted POSIX Message Queue File System.686machine # [ 7.844588] systemd[1]: Mounted Kernel Debug File System.687machine # [ 7.847961] systemd[1]: Mounted Kernel Trace File System.688machine # [ 7.848528] systemd[1]: Mounted Kernel Configuration File System.689machine # [ 7.849070] systemd[1]: Mounted FUSE Control File System.690machine # [ 7.873659] systemd[1]: Finished Create List of Static Device Nodes.691machine # [ 7.877161] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...692machine # [ 7.912194] systemd-journald[286]: Collecting audit messages is enabled.693machine # [ 7.929745] systemd[1]: Started Journal Service.694machine # [ 7.929364] systemd[1]: Queued start job for default target Multi-User System.695machine # [ 7.931871] systemd[1]: systemd-journald.service: Deactivated successfully.696machine # [ 7.934485] systemd-modules-load[287]: Using 2 probe threads697machine # [ 7.935688] systemd-modules-load[287]: Module 'atkbd' is built in698machine # [ 7.936977] systemd-modules-load[287]: Module 'loop' is built in699machine # [ 7.950256] systemd[1]: Finished Load Kernel Modules.700machine # [ 7.967718] systemd[1]: Starting Apply Kernel Variables...701machine # [ 7.987849] EXT4-fs (vda): re-mounted 18634b26-91c0-4be2-beef-b30608c30f9c.702machine # [ 7.990276] systemd[1]: Finished Remount Root and Kernel File Systems.703machine # [ 7.992847] systemd[1]: Listening on Disk Image Download Service Socket.704machine # [ 8.003673] systemd[1]: Starting Flush Journal to Persistent Storage...705machine # [ 8.008465] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore706machine # [ 8.021491] systemd[1]: Starting Load/Save OS Random Seed...707machine # [ 8.028375] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os708machine # [ 8.030999] systemd-oomd[288]: No swap; memory pressure usage will be degraded709machine # [ 8.032716] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.710machine # [ 8.060477] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.711machine # [ 8.065779] systemd[1]: Starting Create Static Device Nodes in /dev...712machine # [ 8.085522] systemd[1]: Finished Apply Kernel Variables.713machine # [ 8.108120] systemd[1]: Finished Load/Save OS Random Seed.714machine # [ 8.109077] systemd[1]: Reached target First Boot Complete.715machine # [ 8.114290] systemd-journald[286]: Received client request to flush runtime journal.716machine # [ 8.151003] systemd[1]: Finished Create Static Device Nodes in /dev.717machine # [ 8.152761] systemd[1]: Reached target Preparation for Local File Systems.718machine # [ 8.153780] systemd[1]: Starting Rule-based Manager for Device Events and Files...719machine # [ 8.168929] systemd[1]: Finished Flush Journal to Persistent Storage.720machine # [ 8.223319] systemd-udevd[314]: Using default interface naming scheme 'v261'.721machine # [ 8.277327] systemd[1]: Started Rule-based Manager for Device Events and Files.722machine # [ 8.586606] systemd[1]: Mounting /run/wrappers...723machine # [ 8.683689] systemd[1]: Mounted /run/wrappers.724machine # [ 8.688171] systemd[1]: Reached target Local File Systems.725machine # [ 8.692169] systemd[1]: Listening on Boot Loader Control Service Socket.726machine # [ 8.698431] systemd[1]: Starting register-nix-paths.service...727machine # [ 8.711732] systemd[1]: Starting Create SUID/SGID Wrappers...728machine # [ 8.713169] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.729machine # [ 8.715048] systemd[1]: Starting Save Transient machine-id to Disk...730machine # [ 8.723425] systemd[1]: Starting Create System Files and Directories...731machine # [ 8.809679] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.732machine # [ 8.818329] systemd[1]: Finished Save Transient machine-id to Disk.733machine # [ 8.861246] systemd[1]: Finished Create System Files and Directories.734machine # [ 8.872385] systemd[1]: Starting Rebuild Journal Catalog...735machine # [ 8.884601] systemd[1]: Starting Record System Boot/Shutdown in UTMP...736machine # [ 8.935310] systemd[1]: Finished Coldplug All udev Devices.737machine # [ 8.947713] systemd[1]: Finished Record System Boot/Shutdown in UTMP.738machine # [ 8.984688] systemd[1]: Finished Rebuild Journal Catalog.739machine # [ 8.991310] systemd[1]: Starting Update is Completed...740machine # [ 9.061168] systemd[1]: Finished Update is Completed.741machine # [ 9.130252] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs742machine # [ 9.166646] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse743machine # [ 9.353683] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.744machine # [ 9.355216] systemd[1]: Finished Create SUID/SGID Wrappers.745machine # [ 9.363902] systemd[1]: Condition check resulted in /dev/hvc0 being skipped.746machine # [ 9.383155] systemd[1]: Condition check resulted in /dev/ttyAMA0 being skipped.747machine # [ 9.392301] systemd[1]: Finished register-nix-paths.service.748machine # [ 9.396290] systemd[1]: Reached target System Initialization.749machine # [ 9.399696] systemd[1]: Started Discard unused filesystem blocks once a week.750machine # [ 9.404595] systemd[1]: Started Daily Cleanup of Temporary Directories.751machine # [ 9.409643] systemd[1]: Reached target Timer Units.752machine # [ 9.413670] systemd[1]: Listening on D-Bus System Message Bus Socket.753machine # [ 9.417243] systemd[1]: Listening on Nix Daemon Socket.754machine # [ 9.419547] systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.755machine # [ 9.423140] systemd[1]: Reached target Socket Units.756machine # [ 9.424009] systemd[1]: Reached target Basic System.757machine # [ 9.426400] systemd[1]: Started backdoor.service.758machine # [ 9.432436] systemd[1]: Starting Import lastlog data into lastlog2 database...759machine # [ 9.440139] systemd[1]: Starting Name Service Cache Daemon (nsncd)...760machine # [ 9.448426] systemd[1]: Starting Post-Boot Actions...761machine # [ 9.461837] systemd[1]: Started Reset console on configuration changes.762machine # [ 9.466654] systemd[1]: Starting resolvconf update...763machine # [ 9.470278] systemd[1]: Started rustfs.service.764machine # [ 9.481132] systemd[1]: Starting rustfs-setup.service...765machine # [ 9.490171] systemd[1]: Starting D-Bus System Message Bus...766machine # [ 9.537280] (udev-worker)[375]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.767machine # [ 9.545378] (udev-worker)[375]: Network interface NamePolicy= disabled on kernel command line.768machine # [ 9.547705] nsncd[416]: Sep 18 13:10:27.431 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"769machine # [ 9.560118] systemd[1]: Started Name Service Cache Daemon (nsncd).770machine # [ 9.563671] systemd[1]: Reached target Host and Network Name Lookups.771machine # connecting to host...772machine # [ 9.572499] systemd[1]: Reached target User and Group Name Lookups.773machine # [ 9.573792] (udev-worker)[367]: Network interface NamePolicy= disabled on kernel command line.774machine # [ 9.574923] systemd[1]: Starting User Login Management...775machine # [ 9.575697] systemd[1]: Finished Post-Boot Actions.776machine # [ 9.590940] systemd[1]: Finished Import lastlog data into lastlog2 database.777machine: Guest shell says: b'Spawning backdoor root shell...\n'778machine: connected to guest root shell779machine: (connecting took 10.05 seconds)780machine: (finished: waiting for the VM to finish booting, in 10.72 seconds)781machine # [ 9.717827] dbus-broker-launch[422]: Looking up NSS user entry for 'systemd-timesync'...782machine # [ 9.736681] dbus-broker-launch[422]: NSS returned no entry for 'systemd-timesync'783machine # [ 9.740867] dbus-broker-launch[422]: Invalid user-name in /nix/store/lhqqfsj2y916xvam3i9y33xds2q8h96z-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"784machine # [ 9.759722] systemd[1]: Started D-Bus System Message Bus.785machine # [ 9.773650] systemd[1]: Stopped target Host and Network Name Lookups.786machine # [ 9.776625] systemd[1]: Stopping Host and Network Name Lookups...787machine # [ 9.777563] systemd[1]: Stopped target User and Group Name Lookups.788machine # [ 9.783551] systemd[1]: Stopping User and Group Name Lookups...789machine # [ 9.786085] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...790machine # [ 9.798956] systemd[1]: nscd.service: Deactivated successfully.791machine # [ 9.799965] systemd[1]: Stopped Name Service Cache Daemon (nsncd).792machine # [ 9.807423] systemd[1]: Starting Name Service Cache Daemon (nsncd)...793machine # [ 9.810803] systemd-logind[443]: New seat seat0.794machine # [ 9.823940] systemd[1]: Started User Login Management.795machine # [ 9.826955] systemd[1]: Starting linger-users.service...796machine # [ 9.846096] dbus-broker-launch[422]: Ready797machine # [ 9.897740] nsncd[509]: Sep 18 13:10:27.784 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"798machine # [ 9.899870] systemd[1]: Started Name Service Cache Daemon (nsncd).799machine # [ 9.907691] systemd[1]: Reached target Host and Network Name Lookups.800machine # [ 9.911036] systemd[1]: Reached target User and Group Name Lookups.801machine # [ 9.914693] systemd-logind[443]: Watching system buttons on /dev/input/event0 (gpio-keys)802machine # [ 9.927524] systemd[1]: linger-users.service: Deactivated successfully.803machine # [ 9.931439] systemd[1]: Finished linger-users.service.804machine # [ 9.941979] systemd[1]: Finished resolvconf update.805machine # [ 9.948268] systemd[1]: Reached target Preparation for Network.806machine # [ 9.949191] systemd[1]: Starting DHCP Client...807machine # [ 9.951837] systemd[1]: Starting Extra networking commands....808machine # [ 9.999080] systemd[1]: Condition check resulted in Virtio network device being skipped.809machine # [ 10.001935] systemd[1]: Starting Address configuration of eth1...810machine # [ 10.032898] mousedev: PS/2 mouse device common for all mice811machine # [ 10.109087] network-addresses-eth1-start[556]: adding address 192.168.1.1/24... done812machine # [ 10.122682] network-addresses-eth1-start[556]: adding address 2001:db8:1::1/64... done813machine # [ 10.140593] systemd[1]: Finished Address configuration of eth1.814machine # [ 10.176502] dhcpcd[560]: dhcpcd-10.3.2 starting815machine # [ 10.184513] dhcpcd[612]: dev: loaded udev816machine # [ 10.210825] 8021q: 802.1Q VLAN Support v1.8817machine # [ 10.211230] 8021q: adding VLAN 0 to HW filter on device eth1818machine # [ 10.277863] cfg80211: Loading compiled-in X.509 certificates for regulatory database819machine # [ 10.290979] systemd[1]: Finished Extra networking commands..820machine # [ 10.297011] systemd[1]: Reached target Network.821machine # [ 10.297804] systemd[1]: Starting PostgreSQL Server...822machine # [ 10.298534] systemd[1]: Starting Permit User Sessions...823machine # [ 10.301667] systemd-logind[443]: Watching system buttons on /dev/input/event1 (QEMU QEMU USB Keyboard)824machine # [ 10.313065] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'825machine # [ 10.313574] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'826machine # [ 10.316335] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2827machine # [ 10.316661] cfg80211: failed to load regulatory.db828machine # [ 10.388338] systemd[1]: Finished Permit User Sessions.829machine # [ 10.393474] systemd[1]: Started Getty on tty1.830machine # [ 10.394909] systemd[1]: Reached target Login Prompts.831machine # [ 10.435204] 8021q: adding VLAN 0 to HW filter on device eth0832machine # [ 10.440113] dhcpcd[612]: eth0: waiting for carrier833machine # [ 10.440991] dhcpcd[612]: libudev: received NULL device834machine # [ 10.441761] dhcpcd[612]: libudev: received NULL device835machine # [ 10.442614] dhcpcd[612]: eth0: carrier acquired836machine # [ 10.452466] dhcpcd[612]: DUID 00:01:00:01:32:3f:f4:c4:52:54:00:12:34:56837machine # [ 10.453492] dhcpcd[612]: eth0: IAID 00:12:34:56838machine # [ 10.454182] dhcpcd[612]: eth0: adding address fe80::5054:ff:fe12:3456839machine # [ 10.550828] postgresql-pre-start[648]: The files belonging to this database system will be owned by user "postgres".840machine # [ 10.553384] postgresql-pre-start[648]: This user must also own the server process.841machine # [ 10.554796] postgresql-pre-start[648]: The database cluster will be initialized with locale "en_US.UTF-8".842machine # [ 10.556298] postgresql-pre-start[648]: The default database encoding has accordingly been set to "UTF8".843machine # [ 10.557513] postgresql-pre-start[648]: The default text search configuration will be set to "english".844machine # [ 10.559350] postgresql-pre-start[648]: Data page checksums are enabled.845machine # [ 10.561115] postgresql-pre-start[648]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok846machine # [ 10.562630] postgresql-pre-start[648]: creating subdirectories ... ok847machine # [ 10.563554] postgresql-pre-start[648]: selecting dynamic shared memory implementation ... posix848machine # [ 10.655331] postgresql-pre-start[648]: selecting default "max_connections" ... 100849machine # [ 10.717646] postgresql-pre-start[648]: selecting default "shared_buffers" ... 128MB850machine # [ 11.110315] input: QEMU Virtio Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:06.0/virtio5/input/input3851machine # [ 11.124513] dhcpcd[612]: eth0: soliciting a DHCP lease852machine # [ 11.137282] dhcpcd[612]: eth0: offered 10.0.2.15 from 10.0.2.2853machine # [ 11.156099] dhcpcd[612]: eth0: probing address 10.0.2.15/24854machine # [ 11.492362] systemd[1]: Starting Virtual Console Setup...855machine # [ 11.514403] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.856machine # [ 11.515542] systemd[1]: Stopped Virtual Console Setup.857machine # [ 11.518068] systemd[1]: Starting Virtual Console Setup...858machine # [ 11.539881] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.859machine # [ 11.582859] systemd-logind[443]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)860machine # [ 11.589580] postgresql-pre-start[648]: selecting default time zone ... UTC861machine # [ 11.590842] postgresql-pre-start[648]: creating configuration files ... ok862machine # [ 11.720745] systemd-vconsole-setup[689]: Configuration of first virtual console was skipped, ignoring remaining ones.863machine # [ 11.725699] systemd[1]: Finished Virtual Console Setup.864machine # [ 11.836377] postgresql-pre-start[648]: running bootstrap script ... ok865machine # [ 12.217616] dhcpcd[612]: eth0: soliciting an IPv6 router866machine # [ 12.222398] dhcpcd[612]: eth0: Router Advertisement from fe80::2867machine # [ 12.225129] dhcpcd[612]: eth0: adding address fec0::5054:ff:fe12:3456/64868machine # [ 12.227867] dhcpcd[612]: eth0: adding route to fec0::/64869machine # [ 12.230425] dhcpcd[612]: eth0: adding default route via fe80::2870machine # [ 12.413519] postgresql-pre-start[648]: performing post-bootstrap initialization ... ok871machine # [ 12.583886] postgresql-pre-start[648]: syncing data to disk ... ok872machine # [ 12.586961] postgresql-pre-start[648]: initdb: warning: enabling "trust" authentication for local connections873machine # [ 12.592406] postgresql-pre-start[648]: 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.874machine # [ 12.599049] postgresql-pre-start[648]: Success. You can now start the database server using:875machine # [ 12.602710] postgresql-pre-start[648]: pg_ctl -D /var/lib/postgresql/18 -l logfile start876machine # [ 12.789577] postgres[708]: [708] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit877machine # [ 12.795331] postgres[708]: [708] LOG: listening on IPv4 address "0.0.0.0", port 5432878machine # [ 12.799081] postgres[708]: [708] LOG: listening on IPv6 address "::", port 5432879machine # [ 12.804359] postgres[708]: [708] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"880machine # [ 12.811883] postgres[717]: [717] LOG: database system was shut down at 2026-09-18 13:10:30 GMT881machine # [ 12.822820] postgres[708]: [708] LOG: database system is ready to accept connections882machine # [ 12.827597] systemd[1]: Started PostgreSQL Server.883machine # [ 12.837899] systemd[1]: Starting PostgreSQL Setup Scripts...884machine # [ 13.186043] postgresql-setup-start[728]: CREATE DATABASE885machine # [ 13.233864] postgresql-setup-start[742]: CREATE ROLE886machine # [ 13.253479] postgresql-setup-start[744]: ALTER DATABASE887machine # [ 13.259923] systemd[1]: Finished PostgreSQL Setup Scripts.888machine # [ 13.261202] systemd[1]: Reached target PostgreSQL.889machine # [ 16.030778] dhcpcd[612]: eth0: leased 10.0.2.15 for 86400 seconds890machine # [ 16.031169] dhcpcd[612]: eth0: adding route to 10.0.2.0/24891machine # [ 16.031309] dhcpcd[612]: eth0: adding default route via 10.0.2.2892machine # [ 16.254041] systemd[1]: Started DHCP Client.893machine # [ 16.255905] systemd[1]: Reached target Network is Online.894machine # [ 16.262787] systemd[1]: Starting k3s service...895machine # [ 16.362688] k3s[825]: time="2026-09-18T13:10:34Z" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock"896machine # [ 16.365889] k3s[825]: time="2026-09-18T13:10:34Z" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/12d1185026784ba3717903546b35f7d424a0c42f9bb75a7f03f0ead9f837718b"897machine # [ 17.203160] rustfs-setup-start[834]: mb s3://niks3898machine # [ 17.214397] systemd[1]: Finished rustfs-setup.service.899machine # [ 19.331105] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Starting k3s 1.35.8+k3s1 (e952d68a)"900machine # [ 19.363581] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Configuring sqlite3 database connection pooling: maxIdle=20, maxOpen=0, maxLifetime=0s, maxIdleTime=2m0s"901machine # [ 19.366984] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Kine built with sqlite from github.com/mattn/go-sqlite3 version 3.53.3"902machine # [ 19.369592] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Configuring database table schema and indexes, this may take a moment..."903machine # [ 19.381180] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Database tables and indexes are up to date"904machine # [ 19.388221] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Running startup VACUUM to reclaim disk space, this may take a moment..."905machine # [ 19.395010] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Startup VACUUM completed successfully"906machine # [ 19.398882] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Kine available at unix://kine.sock"907machine # [ 19.402651] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"908machine # [ 19.407346] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="Datastore connection validated successfully, proceeding with bootstrap data generation"909machine # [ 19.412304] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="generated self-signed CA certificate CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:37.28067892 +0000 UTC notAfter=2036-09-15 12:10:37.28067892 +0000 UTC"910machine # [ 19.418534] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"911machine # [ 19.424319] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=system:k3s-supervisor,O=system:masters signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"912machine # [ 19.429551] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"913machine # [ 19.434297] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"914machine # [ 19.438641] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=system:apiserver,O=system:masters signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"915machine # [ 19.442988] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"916machine # [ 19.447049] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="generated self-signed CA certificate CN=k3s-server-ca@1789737037: notBefore=2026-09-18 12:10:37.28800056 +0000 UTC notAfter=2036-09-15 12:10:37.28800056 +0000 UTC"917machine # [ 19.450897] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"918machine # [ 19.454347] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=kube-scheduler signed by CN=k3s-server-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"919machine # [ 19.457713] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=kube-controller-manager signed by CN=k3s-server-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"920machine # [ 19.461041] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="generated self-signed CA certificate CN=k3s-request-header-ca@1789737037: notBefore=2026-09-18 12:10:37.29713032 +0000 UTC notAfter=2036-09-15 12:10:37.29713032 +0000 UTC"921machine # [ 19.464350] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"922machine # [ 19.467328] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="generated self-signed CA certificate CN=etcd-server-ca@1789737037: notBefore=2026-09-18 12:10:37.29837966 +0000 UTC notAfter=2036-09-15 12:10:37.29837966 +0000 UTC"923machine # [ 19.470430] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"924machine # [ 19.473353] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="generated self-signed CA certificate CN=etcd-peer-ca@1789737037: notBefore=2026-09-18 12:10:37.29960972 +0000 UTC notAfter=2036-09-15 12:10:37.29960972 +0000 UTC"925machine # [ 19.476541] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"926machine # [ 19.479431] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"927machine # [ 19.482326] k3s[825]: time="2026-09-18T13:10:37Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1789737037: notBefore=2026-09-18 12:10:37 +0000 UTC notAfter=2027-09-18 12:10:37 +0000 UTC"928machine # [ 19.485056] k3s[825]: time="2026-09-18T13:10:37Z" level=warning msg="dynamiclistener [::]:6443: no cached certificate available for preload - deferring certificate load until storage initialization or first client request"929machine # [ 19.487862] k3s[825]: time="2026-09-18T13:10:37Z" 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__4c7f_95fe_5646_4f70-7ad840:fec0::4c7f:95fe:5646:4f70 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=057231EC9618D2113027533CE60C26CFEB1B59EA]"930machine # [ 20.601376] k3s[825]: time="2026-09-18T13:10:38Z" level=info msg="Password verified locally for node machine"931machine # [ 20.601901] k3s[825]: time="2026-09-18T13:10:38Z" level=info msg="certificate CN=machine signed by CN=k3s-server-ca@1789737037: notBefore=2026-09-18 12:10:38 +0000 UTC notAfter=2027-09-18 12:10:38 +0000 UTC"932machine # [ 20.924736] k3s[825]: time="2026-09-18T13:10:38Z" level=info msg="certificate CN=system:node:machine,O=system:nodes signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:38 +0000 UTC notAfter=2027-09-18 12:10:38 +0000 UTC"933machine # [ 21.047680] k3s[825]: time="2026-09-18T13:10:38Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:38 +0000 UTC notAfter=2027-09-18 12:10:38 +0000 UTC"934machine # [ 21.226500] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1789737037: notBefore=2026-09-18 12:10:39 +0000 UTC notAfter=2027-09-18 12:10:39 +0000 UTC"935machine # [ 21.362616] k3s[825]: time="2026-09-18T13:10:39Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:55282: runtime core not ready"936machine # [ 21.541263] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Module overlay was already loaded"937machine # [ 21.646054] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.938machine # [ 21.652838] Bridge firewalling registered939machine # [ 21.665998] k3s[825]: time="2026-09-18T13:10:39Z" level=warning msg="Failed to load kernel module iptable_nat with modprobe"940machine # [ 21.679793] k3s[825]: time="2026-09-18T13:10:39Z" level=warning msg="Failed to load kernel module iptable_filter with modprobe"941machine # [ 21.687504] k3s[825]: time="2026-09-18T13:10:39Z" level=warning msg="Failed to load kernel module nft-expr-counter with modprobe"942machine # [ 21.790303] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Set sysctl 'net/ipv4/conf/default/forwarding' to 1"943machine # [ 21.794121] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_max' to 131072"944machine # [ 21.798010] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400"945machine # [ 21.802274] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_close_wait' to 3600"946machine # [ 21.805970] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Set sysctl 'net/ipv4/conf/all/forwarding' to 1"947machine # [ 21.812746] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Creating k3s-cert-monitor event broadcaster"948machine # [ 21.816588] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Connecting to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"949machine # [ 21.820785] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Saving cluster bootstrap data to datastore"950machine # [ 21.824338] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Polling for API server readiness: GET /readyz failed: the server is currently unable to handle the request"951machine # [ 21.828837] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Handling backend connection request [machine]"952machine # [ 21.831197] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"953machine # [ 21.833911] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Remotedialer connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"954machine # [ 21.836868] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"955machine # [ 21.839357] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Connection to etcd is ready"956machine # [ 21.841401] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="ETCD server is now running"957machine # [ 21.843364] k3s[825]: time="2026-09-18T13:10:39Z" 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"958machine # [ 21.874707] k3s[825]: time="2026-09-18T13:10:39Z" 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"959machine # [ 21.882315] k3s[825]: time="2026-09-18T13:10:39Z" 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"960machine # [ 21.902623] k3s[825]: time="2026-09-18T13:10:39Z" 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"961machine # [ 21.910614] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"962machine # [ 21.912284] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="To join server node to cluster: k3s server -s https://10.0.2.15:6443 -t ${SERVER_NODE_TOKEN}"963machine # [ 21.914160] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"964machine # [ 21.915853] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="To join agent node to cluster: k3s agent -s https://10.0.2.15:6443 -t ${AGENT_NODE_TOKEN}"965machine # [ 21.917760] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"966machine # [ 21.919117] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Run: k3s kubectl"967machine # [ 21.920218] k3s[825]: I0918 13:10:39.732398 825 options.go:263] external host was not specified, using 10.0.2.15968machine # [ 21.921653] k3s[825]: I0918 13:10:39.737835 825 server.go:158] Version: v1.35.8+k3s1969machine # [ 21.922796] k3s[825]: I0918 13:10:39.737897 825 server.go:160] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""970machine # [ 21.947753] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log"971machine # [ 21.966293] k3s[825]: time="2026-09-18T13:10:39Z" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml"972machine # [ 22.041555] k3s[825]: time="2026-09-18T13:10:39Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:55350: runtime core not ready"973machine # [ 22.206186] k3s[825]: time="2026-09-18T13:10:40Z" 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"974machine # [ 22.231070] k3s[825]: I0918 13:10:40.119070 825 shared_informer.go:349] "Waiting for caches to sync" controller="node_authorizer"975machine # [ 22.235867] k3s[825]: I0918 13:10:40.124066 825 shared_informer.go:370] "Waiting for caches to sync"976machine # [ 22.238643] k3s[825]: I0918 13:10:40.126830 825 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.977machine # [ 22.245213] k3s[825]: I0918 13:10:40.126918 825 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.978machine # [ 22.250596] k3s[825]: I0918 13:10:40.127391 825 instance.go:240] Using reconciler: lease979machine # [ 22.251776] k3s[825]: I0918 13:10:40.136899 825 handler.go:304] Adding GroupVersion apiextensions.k8s.io v1 to ResourceManager980machine # [ 22.253749] k3s[825]: W0918 13:10:40.136928 825 genericapiserver.go:787] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources.981machine # [ 22.255798] k3s[825]: I0918 13:10:40.141946 825 cidrallocator.go:198] starting ServiceCIDR Allocator Controller982machine # [ 22.306762] k3s[825]: I0918 13:10:40.194923 825 handler.go:304] Adding GroupVersion v1 to ResourceManager983machine # [ 22.309321] k3s[825]: I0918 13:10:40.195231 825 apis.go:112] API group "internal.apiserver.k8s.io" is not enabled, skipping.984machine # [ 22.356161] k3s[825]: I0918 13:10:40.243247 825 apis.go:112] API group "storagemigration.k8s.io" is not enabled, skipping.985machine # [ 22.416429] k3s[825]: I0918 13:10:40.304612 825 handler.go:304] Adding GroupVersion authentication.k8s.io v1 to ResourceManager986machine # [ 22.418112] k3s[825]: W0918 13:10:40.304654 825 genericapiserver.go:787] Skipping API authentication.k8s.io/v1beta1 because it has no resources.987machine # [ 22.422256] k3s[825]: W0918 13:10:40.304662 825 genericapiserver.go:787] Skipping API authentication.k8s.io/v1alpha1 because it has no resources.988machine # [ 22.424169] k3s[825]: I0918 13:10:40.305121 825 handler.go:304] Adding GroupVersion authorization.k8s.io v1 to ResourceManager989machine # [ 22.425744] k3s[825]: W0918 13:10:40.305133 825 genericapiserver.go:787] Skipping API authorization.k8s.io/v1beta1 because it has no resources.990machine # [ 22.427516] k3s[825]: I0918 13:10:40.305989 825 handler.go:304] Adding GroupVersion autoscaling v2 to ResourceManager991machine # [ 22.429022] k3s[825]: I0918 13:10:40.306659 825 handler.go:304] Adding GroupVersion autoscaling v1 to ResourceManager992machine # [ 22.430497] k3s[825]: W0918 13:10:40.306672 825 genericapiserver.go:787] Skipping API autoscaling/v2beta1 because it has no resources.993machine # [ 22.432081] k3s[825]: W0918 13:10:40.306679 825 genericapiserver.go:787] Skipping API autoscaling/v2beta2 because it has no resources.994machine # [ 22.433617] k3s[825]: I0918 13:10:40.307975 825 handler.go:304] Adding GroupVersion batch v1 to ResourceManager995machine # [ 22.434916] k3s[825]: W0918 13:10:40.307992 825 genericapiserver.go:787] Skipping API batch/v1beta1 because it has no resources.996machine # [ 22.436449] k3s[825]: I0918 13:10:40.308831 825 handler.go:304] Adding GroupVersion certificates.k8s.io v1 to ResourceManager997machine # [ 22.437915] k3s[825]: W0918 13:10:40.308849 825 genericapiserver.go:787] Skipping API certificates.k8s.io/v1beta1 because it has no resources.998machine # [ 22.439569] k3s[825]: W0918 13:10:40.308871 825 genericapiserver.go:787] Skipping API certificates.k8s.io/v1alpha1 because it has no resources.999machine # [ 22.443148] k3s[825]: I0918 13:10:40.309583 825 handler.go:304] Adding GroupVersion coordination.k8s.io v1 to ResourceManager1000machine # [ 22.446080] k3s[825]: W0918 13:10:40.309606 825 genericapiserver.go:787] Skipping API coordination.k8s.io/v1beta1 because it has no resources.1001machine # [ 22.447736] k3s[825]: W0918 13:10:40.309613 825 genericapiserver.go:787] Skipping API coordination.k8s.io/v1alpha2 because it has no resources.1002machine # [ 22.449545] k3s[825]: I0918 13:10:40.310165 825 handler.go:304] Adding GroupVersion discovery.k8s.io v1 to ResourceManager1003machine # [ 22.451085] k3s[825]: W0918 13:10:40.310177 825 genericapiserver.go:787] Skipping API discovery.k8s.io/v1beta1 because it has no resources.1004machine # [ 22.452951] k3s[825]: I0918 13:10:40.312452 825 handler.go:304] Adding GroupVersion networking.k8s.io v1 to ResourceManager1005machine # [ 22.454507] k3s[825]: W0918 13:10:40.312471 825 genericapiserver.go:787] Skipping API networking.k8s.io/v1beta1 because it has no resources.1006machine # [ 22.456272] k3s[825]: I0918 13:10:40.312895 825 handler.go:304] Adding GroupVersion node.k8s.io v1 to ResourceManager1007machine # [ 22.457674] k3s[825]: W0918 13:10:40.312905 825 genericapiserver.go:787] Skipping API node.k8s.io/v1beta1 because it has no resources.1008machine # [ 22.459249] k3s[825]: W0918 13:10:40.312911 825 genericapiserver.go:787] Skipping API node.k8s.io/v1alpha1 because it has no resources.1009machine # [ 22.460937] k3s[825]: I0918 13:10:40.313594 825 handler.go:304] Adding GroupVersion policy v1 to ResourceManager1010machine # [ 22.462268] k3s[825]: W0918 13:10:40.313607 825 genericapiserver.go:787] Skipping API policy/v1beta1 because it has no resources.1011machine # [ 22.463781] k3s[825]: I0918 13:10:40.315176 825 handler.go:304] Adding GroupVersion rbac.authorization.k8s.io v1 to ResourceManager1012machine # [ 22.465414] k3s[825]: W0918 13:10:40.315193 825 genericapiserver.go:787] Skipping API rbac.authorization.k8s.io/v1beta1 because it has no resources.1013machine # [ 22.467218] k3s[825]: W0918 13:10:40.315200 825 genericapiserver.go:787] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources.1014machine # [ 22.469037] k3s[825]: I0918 13:10:40.315628 825 handler.go:304] Adding GroupVersion scheduling.k8s.io v1 to ResourceManager1015machine # [ 22.470505] k3s[825]: W0918 13:10:40.315639 825 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1beta1 because it has no resources.1016machine # [ 22.472177] k3s[825]: W0918 13:10:40.315648 825 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources.1017machine # [ 22.473811] k3s[825]: I0918 13:10:40.317990 825 handler.go:304] Adding GroupVersion storage.k8s.io v1 to ResourceManager1018machine # [ 22.475208] k3s[825]: W0918 13:10:40.318021 825 genericapiserver.go:787] Skipping API storage.k8s.io/v1beta1 because it has no resources.1019machine # [ 22.480284] k3s[825]: W0918 13:10:40.318029 825 genericapiserver.go:787] Skipping API storage.k8s.io/v1alpha1 because it has no resources.1020machine # [ 22.481883] k3s[825]: I0918 13:10:40.319186 825 handler.go:304] Adding GroupVersion flowcontrol.apiserver.k8s.io v1 to ResourceManager1021machine # [ 22.483420] k3s[825]: W0918 13:10:40.319205 825 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta3 because it has no resources.1022machine # [ 22.488128] k3s[825]: W0918 13:10:40.319213 825 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta2 because it has no resources.1023machine # [ 22.489884] k3s[825]: W0918 13:10:40.319217 825 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta1 because it has no resources.1024machine # [ 22.491618] k3s[825]: I0918 13:10:40.322773 825 handler.go:304] Adding GroupVersion apps v1 to ResourceManager1025machine # [ 22.495356] k3s[825]: W0918 13:10:40.322801 825 genericapiserver.go:787] Skipping API apps/v1beta2 because it has no resources.1026machine # [ 22.496942] k3s[825]: W0918 13:10:40.322808 825 genericapiserver.go:787] Skipping API apps/v1beta1 because it has no resources.1027machine # [ 22.498400] k3s[825]: I0918 13:10:40.324597 825 handler.go:304] Adding GroupVersion admissionregistration.k8s.io v1 to ResourceManager1028machine # [ 22.499952] k3s[825]: W0918 13:10:40.324618 825 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources.1029machine # [ 22.504135] k3s[825]: W0918 13:10:40.324633 825 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources.1030machine # [ 22.505900] k3s[825]: I0918 13:10:40.325224 825 handler.go:304] Adding GroupVersion events.k8s.io v1 to ResourceManager1031machine # [ 22.507291] k3s[825]: W0918 13:10:40.325240 825 genericapiserver.go:787] Skipping API events.k8s.io/v1beta1 because it has no resources.1032machine # [ 22.512069] k3s[825]: I0918 13:10:40.326965 825 handler.go:304] Adding GroupVersion resource.k8s.io v1 to ResourceManager1033machine # [ 22.513578] k3s[825]: W0918 13:10:40.326984 825 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta2 because it has no resources.1034machine # [ 22.515127] k3s[825]: W0918 13:10:40.326990 825 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta1 because it has no resources.1035machine # [ 22.520146] k3s[825]: W0918 13:10:40.326995 825 genericapiserver.go:787] Skipping API resource.k8s.io/v1alpha3 because it has no resources.1036machine # [ 22.521785] k3s[825]: I0918 13:10:40.330062 825 handler.go:304] Adding GroupVersion apiregistration.k8s.io v1 to ResourceManager1037machine # [ 22.523265] k3s[825]: W0918 13:10:40.330080 825 genericapiserver.go:787] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources.1038machine # [ 23.070420] k3s[825]: time="2026-09-18T13:10:40Z" level=info msg="containerd is now running"1039machine # [ 23.076923] k3s[825]: time="2026-09-18T13:10:40Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/k3s-airgap-images-arm64.tar.zst"1040machine # [ 23.120115] k3s[825]: I0918 13:10:41.006779 825 secure_serving.go:211] Serving securely on 127.0.0.1:64441041machine # [ 23.121552] k3s[825]: I0918 13:10:41.007230 825 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"1042machine # [ 23.123599] k3s[825]: I0918 13:10:41.007365 825 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"1043machine # [ 23.128205] k3s[825]: I0918 13:10:41.007447 825 tlsconfig.go:243] "Starting DynamicServingCertificateController"1044machine # [ 23.129570] k3s[825]: I0918 13:10:41.007554 825 controller.go:80] Starting OpenAPI V3 AggregationController1045machine # [ 23.130841] k3s[825]: I0918 13:10:41.007618 825 controller.go:113] "Deleting old lease on startup" lease="kube-system/apiserver-ik4pcwfs7qgdl76byc4pomgvia"1046machine # [ 23.136229] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Starting apiserver lease garbage collector" logger=k3s1047machine # [ 23.137643] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Waiting for caches to sync" logger=k3s1048machine # [ 23.138910] k3s[825]: I0918 13:10:41.009247 825 cluster_authentication_trust_controller.go:459] Starting cluster_authentication_trust_controller controller1049machine # [ 23.144124] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Waiting for caches to sync" logger=k3s1050machine # [ 23.145374] k3s[825]: I0918 13:10:41.009320 825 apf_controller.go:377] Starting API Priority and Fairness config controller1051machine # [ 23.146777] k3s[825]: I0918 13:10:41.009386 825 local_available_controller.go:156] Starting LocalAvailability controller1052machine # [ 23.148212] k3s[825]: I0918 13:10:41.009395 825 cache.go:32] Waiting for caches to sync for LocalAvailability controller1053machine # [ 23.149597] k3s[825]: I0918 13:10:41.009424 825 apiservice_controller.go:100] Starting APIServiceRegistrationController1054machine # [ 23.150957] k3s[825]: I0918 13:10:41.009431 825 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller1055machine # [ 23.156182] k3s[825]: I0918 13:10:41.009626 825 customresource_discovery_controller.go:294] Starting DiscoveryController1056machine # [ 23.157677] k3s[825]: I0918 13:10:41.009659 825 system_namespaces_controller.go:66] Starting system namespaces controller1057machine # [ 23.159080] k3s[825]: I0918 13:10:41.010076 825 aggregator.go:185] waiting for initial CRD sync...1058machine # [ 23.160321] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Starting legacy_token_tracking_controller" logger=k3s1059machine # [ 23.161699] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Waiting for caches to sync" logger=k3s1060machine # [ 23.162902] k3s[825]: I0918 13:10:41.010379 825 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"1061machine # [ 23.168163] k3s[825]: I0918 13:10:41.010496 825 remote_available_controller.go:425] Starting RemoteAvailability controller1062machine # [ 23.169614] k3s[825]: I0918 13:10:41.010506 825 cache.go:32] Waiting for caches to sync for RemoteAvailability controller1063machine # [ 23.171024] k3s[825]: I0918 13:10:41.010530 825 controller.go:78] Starting OpenAPI AggregationController1064machine # [ 23.176162] k3s[825]: I0918 13:10:41.010569 825 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"1065machine # [ 23.178117] k3s[825]: I0918 13:10:41.011373 825 repairip.go:210] Starting ipallocator-repair-controller1066machine # [ 23.179346] k3s[825]: I0918 13:10:41.011391 825 shared_informer.go:349] "Waiting for caches to sync" controller="ipallocator-repair-controller"1067machine # [ 23.181092] k3s[825]: I0918 13:10:41.020713 825 default_servicecidr_controller.go:110] Starting kubernetes-service-cidr-controller1068machine # [ 23.182603] k3s[825]: I0918 13:10:41.020745 825 shared_informer.go:349] "Waiting for caches to sync" controller="kubernetes-service-cidr-controller"1069machine # [ 23.184364] k3s[825]: I0918 13:10:41.020829 825 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"1070machine # [ 23.186283] k3s[825]: I0918 13:10:41.020936 825 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"1071machine # [ 23.188332] k3s[825]: I0918 13:10:41.021305 825 controller.go:142] Starting OpenAPI controller1072machine # [ 23.189475] k3s[825]: I0918 13:10:41.021352 825 controller.go:90] Starting OpenAPI V3 controller1073machine # [ 23.190633] k3s[825]: I0918 13:10:41.021375 825 naming_controller.go:305] Starting NamingConditionController1074machine # [ 23.191922] k3s[825]: I0918 13:10:41.021445 825 nonstructuralschema_controller.go:202] Starting NonStructuralSchemaConditionController1075machine # [ 23.194106] k3s[825]: I0918 13:10:41.021463 825 apiapproval_controller.go:196] Starting KubernetesAPIApprovalPolicyConformantConditionController1076machine # [ 23.197266] k3s[825]: I0918 13:10:41.021480 825 crd_finalizer.go:273] Starting CRDFinalizer1077machine # [ 23.200168] k3s[825]: I0918 13:10:41.021530 825 crdregistration_controller.go:114] Starting crd-autoregister controller1078machine # [ 23.201784] k3s[825]: I0918 13:10:41.021540 825 shared_informer.go:349] "Waiting for caches to sync" controller="crd-autoregister"1079machine # [ 23.232643] k3s[825]: I0918 13:10:41.120846 825 shared_informer.go:356] "Caches are synced" controller="kubernetes-service-cidr-controller"1080machine # [ 23.236069] k3s[825]: I0918 13:10:41.122827 825 default_servicecidr_controller.go:169] Creating default ServiceCIDR with CIDRs: [10.43.0.0/16]1081machine # [ 23.237810] k3s[825]: I0918 13:10:41.123574 825 shared_informer.go:356] "Caches are synced" controller="crd-autoregister"1082machine # [ 23.239245] k3s[825]: I0918 13:10:41.123643 825 aggregator.go:187] initial CRD sync complete...1083machine # [ 23.243021] k3s[825]: I0918 13:10:41.123652 825 autoregister_controller.go:144] Starting autoregister controller1084machine # [ 23.244511] k3s[825]: I0918 13:10:41.123663 825 cache.go:32] Waiting for caches to sync for autoregister controller1085machine # [ 23.245869] k3s[825]: I0918 13:10:41.123670 825 cache.go:39] Caches are synced for autoregister controller1086machine # [ 23.267439] k3s[825]: I0918 13:10:41.155651 825 shared_informer.go:356] "Caches are synced" controller="node_authorizer"1087machine # [ 23.270641] k3s[825]: I0918 13:10:41.157325 825 shared_informer.go:377] "Caches are synced"1088machine # [ 23.271849] k3s[825]: I0918 13:10:41.157362 825 policy_source.go:248] refreshing policies1089machine # [ 23.320392] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Caches are synced" logger=k3s1090machine # [ 23.324085] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Caches are synced" logger=k3s1091machine # [ 23.325385] k3s[825]: I0918 13:10:41.210631 825 cache.go:39] Caches are synced for RemoteAvailability controller1092machine # [ 23.326707] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Caches are synced" logger=k3s1093machine # [ 23.327823] k3s[825]: I0918 13:10:41.210721 825 apf_controller.go:382] Running API Priority and Fairness config worker1094machine # [ 23.332152] k3s[825]: I0918 13:10:41.210729 825 apf_controller.go:385] Running API Priority and Fairness periodic rebalancing process1095machine # [ 23.333782] k3s[825]: I0918 13:10:41.210872 825 cache.go:39] Caches are synced for LocalAvailability controller1096machine # [ 23.335120] k3s[825]: I0918 13:10:41.210893 825 cache.go:39] Caches are synced for APIServiceRegistrationController controller1097machine # [ 23.338191] k3s[825]: I0918 13:10:41.211457 825 shared_informer.go:356] "Caches are synced" controller="ipallocator-repair-controller"1098machine # [ 23.339795] k3s[825]: I0918 13:10:41.211925 825 handler_discovery.go:451] Starting ResourceDiscoveryManager1099machine # [ 23.342817] k3s[825]: I0918 13:10:41.218567 825 controller.go:667] quota admission added evaluator for: namespaces1100machine # [ 23.351580] k3s[825]: I0918 13:10:41.239081 825 controller.go:667] quota admission added evaluator for: leases.coordination.k8s.io1101machine # [ 23.373656] k3s[825]: I0918 13:10:41.261865 825 cidrallocator.go:302] created ClusterIP allocator for Service CIDR 10.43.0.0/161102machine # [ 23.375552] k3s[825]: I0918 13:10:41.263795 825 default_servicecidr_controller.go:231] Setting default ServiceCIDR condition Ready to True1103machine # [ 23.391980] k3s[825]: I0918 13:10:41.280187 825 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161104machine # [ 23.409661] k3s[825]: I0918 13:10:41.297817 825 alloc.go:329] "allocated clusterIPs" service="default/kubernetes" clusterIPs={"IPv4":"10.43.0.1"}1105machine # [ 23.436916] k3s[825]: W0918 13:10:41.325088 825 lease.go:265] Resetting endpoints for master service "kubernetes" to [10.0.2.15]1106machine # [ 23.440856] k3s[825]: I0918 13:10:41.329031 825 controller.go:667] quota admission added evaluator for: endpoints1107machine # [ 23.447501] k3s[825]: I0918 13:10:41.335671 825 controller.go:667] quota admission added evaluator for: endpointslices.discovery.k8s.io1108machine # [ 23.465310] k3s[825]: E0918 13:10:41.353483 825 controller.go:102] Error removing old endpoints from kubernetes service: no API server IP addresses were listed in storage, refusing to erase all endpoints for the kubernetes Service1109machine # [ 23.799296] k3s[825]: time="2026-09-18T13:10:41Z" level=info msg="Polling for API server readiness: GET /readyz failed: unknown"1110machine # [ 24.129096] k3s[825]: I0918 13:10:42.016723 825 storage_scheduling.go:123] created PriorityClass system-node-critical with value 20000010001111machine # [ 24.136505] k3s[825]: I0918 13:10:42.024714 825 storage_scheduling.go:123] created PriorityClass system-cluster-critical with value 20000000001112machine # [ 24.139557] k3s[825]: I0918 13:10:42.026635 825 storage_scheduling.go:139] all system priority classes are created successfully or already exist.1113machine # [ 24.981890] k3s[825]: I0918 13:10:42.868885 825 controller.go:667] quota admission added evaluator for: roles.rbac.authorization.k8s.io1114machine # [ 25.046320] k3s[825]: I0918 13:10:42.934482 825 controller.go:667] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io1115machine # [ 25.827210] k3s[825]: time="2026-09-18T13:10:43Z" level=info msg="Waiting for untainted node"1116machine # [ 25.829115] k3s[825]: time="2026-09-18T13:10:43Z" level=info msg="Kube API server is now running"1117machine # [ 25.832371] k3s[825]: time="2026-09-18T13:10:43Z" level=info msg="k3s is up and running"1118machine # [ 25.833725] k3s[825]: time="2026-09-18T13:10:43Z" level=info msg="Creating k3s-supervisor event broadcaster"1119machine # [ 25.837931] systemd[1]: Started k3s service.1120machine # [ 25.838702] systemd[1]: Reached target Multi-User System.1121machine # [ 25.839502] systemd[1]: Startup finished in 670ms (kernel) + 5.237s (initrd) + 19.927s (userspace) = 25.835s.1122machine # [ 25.847304] k3s[825]: time="2026-09-18T13:10:43Z" 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=Normal1123machine # [ 25.870582] k3s[825]: I0918 13:10:43.758780 825 controllermanager.go:189] "Starting" version="v1.35.8+k3s1"1124machine # [ 25.873004] k3s[825]: I0918 13:10:43.760438 825 controllermanager.go:191] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1125machine # [ 25.880688] k3s[825]: I0918 13:10:43.768889 825 secure_serving.go:211] Serving securely on 127.0.0.1:102571126machine # [ 25.883612] k3s[825]: I0918 13:10:43.771747 825 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1127machine # [ 25.885551] k3s[825]: I0918 13:10:43.771803 825 shared_informer.go:370] "Waiting for caches to sync"1128machine # [ 25.887005] k3s[825]: I0918 13:10:43.771858 825 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"1129machine # [ 25.893020] k3s[825]: I0918 13:10:43.772009 825 tlsconfig.go:243] "Starting DynamicServingCertificateController"1130machine # [ 25.894873] k3s[825]: I0918 13:10:43.772102 825 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1131machine # [ 25.897255] k3s[825]: I0918 13:10:43.772137 825 shared_informer.go:370] "Waiting for caches to sync"1132machine # [ 25.898859] k3s[825]: I0918 13:10:43.772152 825 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1133machine # [ 25.902038] k3s[825]: I0918 13:10:43.772165 825 shared_informer.go:370] "Waiting for caches to sync"1134machine # [ 25.906935] k3s[825]: I0918 13:10:43.794311 825 controller.go:667] quota admission added evaluator for: serviceaccounts1135machine # [ 25.969359] k3s[825]: time="2026-09-18T13:10:43Z" level=info msg="Creating embedded CRD etcdsnapshotfiles.k3s.cattle.io"1136machine # [ 25.988105] k3s[825]: I0918 13:10:43.874411 825 shared_informer.go:377] "Caches are synced"1137machine # [ 25.989450] k3s[825]: I0918 13:10:43.875241 825 shared_informer.go:377] "Caches are synced"1138machine # [ 25.991304] k3s[825]: I0918 13:10:43.875331 825 shared_informer.go:377] "Caches are synced"1139machine # [ 25.996412] k3s[825]: time="2026-09-18T13:10:43Z" level=info msg="Creating embedded CRD addons.k3s.cattle.io"1140machine # [ 26.020154] k3s[825]: time="2026-09-18T13:10:43Z" level=info msg="Creating embedded CRD helmchartconfigs.helm.cattle.io"1141machine: (finished: waiting for unit k3s.service, in 27.13 seconds)1142machine # [ 26.040103] k3s[825]: I0918 13:10:43.927241 825 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1143machine: waiting for unit rustfs-setup.service1144machine # [ 26.041613] k3s[825]: I0918 13:10:43.929093 825 shared_informer.go:370] "Waiting for caches to sync"1145machine # [ 26.059084] k3s[825]: time="2026-09-18T13:10:43Z" level=info msg="Creating embedded CRD helmcharts.helm.cattle.io"1146machine # [ 26.091172] k3s[825]: I0918 13:10:43.979212 825 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1147machine # [ 26.125879] k3s[825]: I0918 13:10:44.013346 825 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1148machine # [ 26.127470] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available"1149machine # [ 26.133737] k3s[825]: I0918 13:10:44.021960 825 controllermanager.go:627] "Warning: controller is disabled" controller="cloud-node-lifecycle-controller"1150machine # [ 26.141171] k3s[825]: I0918 13:10:44.029369 825 shared_informer.go:377] "Caches are synced"1151machine # [ 26.148106] k3s[825]: I0918 13:10:44.034258 825 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller" requiredFeatureGates=["ClusterTrustBundle"]1152machine # [ 26.150898] k3s[825]: I0918 13:10:44.034346 825 controllermanager.go:579] "Warning: skipping controller" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller"1153machine # [ 26.155258] k3s[825]: I0918 13:10:44.034357 825 controllermanager.go:627] "Warning: controller is disabled" controller="node-route-controller"1154machine # [ 26.178568] k3s[825]: I0918 13:10:44.066725 825 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1155machine: (finished: waiting for unit rustfs-setup.service, in 0.16 seconds)1156machine: waiting for unit postgresql.service1157machine: (finished: waiting for unit postgresql.service, in 0.10 seconds)1158subtest: chart deploys and becomes ready1159??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1160 File "/nix/store/yyamlhbvx0lp00fbf9sswdcq9ckfh7qj-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391161machine: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s1162??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1163 File "/nix/store/yyamlhbvx0lp00fbf9sswdcq9ckfh7qj-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391164machine # [ 26.366585] k3s[825]: I0918 13:10:44.254616 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="statefulsets.apps"1165machine # [ 26.371242] k3s[825]: I0918 13:10:44.254733 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="horizontalpodautoscalers.autoscaling"1166machine # [ 26.376335] k3s[825]: I0918 13:10:44.254764 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="cronjobs.batch"1167machine # [ 26.378575] k3s[825]: I0918 13:10:44.254800 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="serviceaccounts"1168machine # [ 26.383577] k3s[825]: I0918 13:10:44.254826 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="replicasets.apps"1169machine # [ 26.386685] k3s[825]: I0918 13:10:44.254929 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmchartconfigs.helm.cattle.io"1170machine # [ 26.392216] k3s[825]: I0918 13:10:44.254960 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpoints"1171machine # [ 26.394206] k3s[825]: I0918 13:10:44.255006 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpointslices.discovery.k8s.io"1172machine # [ 26.400213] k3s[825]: I0918 13:10:44.255038 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmcharts.helm.cattle.io"1173machine # [ 26.402370] k3s[825]: I0918 13:10:44.255080 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="controllerrevisions.apps"1174machine # [ 26.407816] k3s[825]: I0918 13:10:44.255104 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="deployments.apps"1175machine # [ 26.411306] k3s[825]: I0918 13:10:44.255136 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="rolebindings.rbac.authorization.k8s.io"1176machine # [ 26.416143] k3s[825]: I0918 13:10:44.255170 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="addons.k3s.cattle.io"1177machine # [ 26.420637] k3s[825]: I0918 13:10:44.255193 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="limitranges"1178machine # [ 26.422722] k3s[825]: I0918 13:10:44.255242 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="podtemplates"1179machine # [ 26.425156] k3s[825]: I0918 13:10:44.255291 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="poddisruptionbudgets.policy"1180machine # [ 26.429951] k3s[825]: I0918 13:10:44.255322 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="roles.rbac.authorization.k8s.io"1181machine # [ 26.436274] k3s[825]: I0918 13:10:44.255353 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="csistoragecapacities.storage.k8s.io"1182machine # [ 26.438526] k3s[825]: I0918 13:10:44.255379 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="resourceclaimtemplates.resource.k8s.io"1183machine # [ 26.444240] k3s[825]: I0918 13:10:44.255407 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="ingresses.networking.k8s.io"1184machine # [ 26.448232] k3s[825]: I0918 13:10:44.255452 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="networkpolicies.networking.k8s.io"1185machine # [ 26.452588] k3s[825]: I0918 13:10:44.255523 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="daemonsets.apps"1186machine # [ 26.456641] k3s[825]: I0918 13:10:44.255582 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="jobs.batch"1187machine # [ 26.458679] k3s[825]: I0918 13:10:44.255613 825 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="leases.coordination.k8s.io"1188machine # Error from server (NotFound): namespaces "niks3" not found1189machine # [ 26.669485] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available"1190machine # [ 26.672099] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-40.1.4+up40.1.0.tgz"1191machine # [ 26.674258] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-40.1.4+up40.1.0.tgz"1192machine # [ 26.677052] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml"1193machine # [ 26.678566] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml"1194machine # [ 26.682611] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml"1195machine # [ 26.684388] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml"1196machine # [ 26.685961] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/runtimes.yaml"1197machine # [ 26.687479] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml"1198machine # [ 26.804126] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Starting dynamiclistener CN filter node controller with SANs: [127.0.0.1 ::1 localhost machine 10.0.2.15 fec0::4c7f:95fe:5646:4f70 10.43.0.1 kubernetes kubernetes.default kubernetes.default.svc kubernetes.default.svc.cluster.local]"1199machine # [ 26.811215] k3s[825]: time="2026-09-18T13:10:44Z" level=info msg="Tunnel server egress proxy mode: agent"1200machine # [ 27.152101] k3s[825]: I0918 13:10:45.039737 825 controllermanager.go:579] "Warning: skipping controller" controller="storage-version-migrator-controller"1201machine # [ 27.155026] k3s[825]: I0918 13:10:45.039776 825 controllermanager.go:627] "Warning: controller is disabled" controller="selinux-warning-controller"1202machine # [ 27.255841] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported docker.io/rancher/klipper-helm:v0.13.3-build20260727"1203machine # [ 27.259156] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Tagged docker.io/rancher/klipper-helm@sha256:5425a2b4613d2458dbdff99218e8d487ebb59c20e7a941f061c0777070f0aac1"1204machine # [ 27.262290] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported docker.io/rancher/klipper-lb:v0.4.17"1205machine # [ 27.263792] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Tagged docker.io/rancher/klipper-lb@sha256:910944bb0bd94f060a82a56ca1ea1c577d3e49b3473a093a47a985f32e92d94a"1206machine # [ 27.266587] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported docker.io/rancher/local-path-provisioner:v0.0.37"1207machine # [ 27.268522] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Tagged docker.io/rancher/local-path-provisioner@sha256:e757967a5ec338f6a9b371c5a9688bedaa8c3578ea3dd4db329ea0084be0a86f"1208machine # [ 27.271404] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported docker.io/rancher/mirrored-coredns-coredns:1.14.6"1209machine # [ 27.272968] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Tagged docker.io/rancher/mirrored-coredns-coredns@sha256:900f9c109f7a33545d3c811516e8376df9019147b750f5ce3e254468769176ea"1210machine # [ 27.275374] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported docker.io/rancher/mirrored-library-busybox:1.37.0"1211machine # [ 27.277221] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Tagged docker.io/rancher/mirrored-library-busybox@sha256:101b4afd76732482eff9b95cae5f94bcf295e521fbec4e01b69c5421f3f3f3e5"1212machine # [ 27.279806] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported docker.io/rancher/mirrored-library-traefik:3.7.8"1213machine # [ 27.281676] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Tagged docker.io/rancher/mirrored-library-traefik@sha256:4299bbed850421258fc5448c2e0e6ad350981d4d335a68de11b92448aedbefe5"1214machine # [ 27.284523] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported docker.io/rancher/mirrored-metrics-server:v0.9.0"1215machine # [ 27.285962] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Tagged docker.io/rancher/mirrored-metrics-server@sha256:d9862115e7c7881280d3d75ca26bda8ffc0fc213315979575bf23ce9826205c0"1216machine # [ 27.288461] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported docker.io/rancher/mirrored-pause:3.10.2"1217machine # [ 27.290048] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Tagged docker.io/rancher/mirrored-pause@sha256:f548e0e8e3dc1896ca956272154dde3314e8cc4fde0a57577ee9fa1c63f5baf4"1218machine # [ 27.474808] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Imported 8 images from /var/lib/rancher/k3s/agent/images/k3s-airgap-images-arm64.tar.zst in 4.39841564s"1219machine # [ 27.477444] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/niks3-server.tar"1220machine # [ 27.479208] k3s[825]: time="2026-09-18T13:10:45Z" 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__4c7f_95fe_5646_4f70-7ad840:fec0::4c7f:95fe:5646:4f70 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=057231EC9618D2113027533CE60C26CFEB1B59EA]"1221machine # [ 27.490486] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Active TLS secret kube-system/k3s-serving (ver=239) (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__4c7f_95fe_5646_4f70-7ad840:fec0::4c7f:95fe:5646:4f70 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=057231EC9618D2113027533CE60C26CFEB1B59EA]"1222machine # [ 27.587209] k3s[825]: time="2026-09-18T13:10:45Z" 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::4c7f:95fe:5646:4f70 --node-labels= --read-only-port=0"1223machine # [ 27.592386] k3s[825]: 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.1224machine # [ 27.604089] k3s[825]: I0918 13:10:45.491769 825 server.go:521] "Kubelet version" kubeletVersion="v1.35.8+k3s1"1225machine # [ 27.605606] k3s[825]: I0918 13:10:45.491803 825 server.go:523] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1226machine # [ 27.607041] k3s[825]: I0918 13:10:45.491834 825 watchdog_linux.go:95] "Systemd watchdog is not enabled"1227machine # [ 27.609918] k3s[825]: I0918 13:10:45.491842 825 watchdog_linux.go:138] "Systemd watchdog is not enabled or the interval is invalid, so health checking will not be started."1228machine # [ 27.612844] k3s[825]: I0918 13:10:45.494425 825 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt"1229machine # [ 27.616187] k3s[825]: I0918 13:10:45.504421 825 server.go:1414] "Using cgroup driver setting received from the CRI runtime" cgroupDriver="systemd"1230machine # [ 27.620701] k3s[825]: I0918 13:10:45.508923 825 server.go:771] "--cgroups-per-qos enabled, but --cgroup-root was not specified. Defaulting to /"1231machine # [ 27.622857] k3s[825]: I0918 13:10:45.508964 825 server.go:832] "NoSwap is set due to memorySwapBehavior not specified" memorySwapBehavior="" FailSwapOn=false1232machine # [ 27.625058] k3s[825]: I0918 13:10:45.509310 825 container_manager_linux.go:272] "Container manager verified user specified cgroup-root exists" cgroupRoot=[]1233machine # [ 27.628676] k3s[825]: I0918 13:10:45.509333 825 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}1234machine # [ 27.645448] k3s[825]: I0918 13:10:45.509650 825 topology_manager.go:143] "Creating topology manager with none policy"1235machine # [ 27.649560] k3s[825]: I0918 13:10:45.509669 825 container_manager_linux.go:308] "Creating device plugin manager"1236machine # [ 27.650990] k3s[825]: I0918 13:10:45.509786 825 container_manager_linux.go:317] "Creating Dynamic Resource Allocation (DRA) manager"1237machine # [ 27.655590] k3s[825]: I0918 13:10:45.515568 825 state_mem.go:41] "Initialized" logger="CPUManager state memory"1238machine # [ 27.658532] k3s[825]: I0918 13:10:45.516014 825 kubelet.go:482] "Attempting to sync node with API server"1239machine # [ 27.661114] k3s[825]: I0918 13:10:45.516530 825 kubelet.go:383] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests"1240machine # [ 27.662773] k3s[825]: I0918 13:10:45.516580 825 kubelet.go:394] "Adding apiserver pod source"1241machine # [ 27.663966] k3s[825]: I0918 13:10:45.516613 825 apiserver.go:42] "Waiting for node sync before watching apiserver pods"1242machine # [ 27.668598] k3s[825]: I0918 13:10:45.518100 825 kuberuntime_manager.go:304] "Container runtime initialized" containerRuntime="containerd" version="2.2.7-k3s1" apiVersion="v1"1243machine # [ 27.670977] k3s[825]: I0918 13:10:45.519108 825 kubelet.go:945] "Not starting ClusterTrustBundle informer because we are in static kubelet mode or the ClusterTrustBundleProjection featuregate is disabled"1244machine # [ 27.676726] k3s[825]: I0918 13:10:45.519138 825 kubelet.go:972] "Not starting PodCertificateRequest manager because we are in static kubelet mode or the PodCertificateProjection feature gate is disabled"1245machine # [ 27.684051] k3s[825]: W0918 13:10:45.519236 825 probe.go:272] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating.1246machine # [ 27.686166] k3s[825]: I0918 13:10:45.537707 825 server.go:1252] "Started kubelet"1247machine # [ 27.687213] k3s[825]: I0918 13:10:45.541138 825 server.go:182] "Starting to listen" address="0.0.0.0" port=102501248machine # [ 27.689331] k3s[825]: I0918 13:10:45.542174 825 ratelimit.go:56] "Setting rate limiting for endpoint" service="podresources" qps=100 burstTokens=101249machine # [ 27.691094] k3s[825]: I0918 13:10:45.542659 825 server_v1.go:49] "podresources" method="list" useActivePods=true1250machine # [ 27.698593] k3s[825]: I0918 13:10:45.543176 825 server.go:254] "Starting to serve the podresources API" endpoint="unix:/var/lib/kubelet/pod-resources/kubelet.sock"1251machine # [ 27.701368] k3s[825]: I0918 13:10:45.546366 825 server.go:317] "Adding debug handlers to kubelet server"1252machine # [ 27.704129] k3s[825]: I0918 13:10:45.556215 825 fs_resource_analyzer.go:69] "Starting FS ResourceAnalyzer"1253machine # [ 27.705468] k3s[825]: I0918 13:10:45.558844 825 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"1254machine # [ 27.710193] k3s[825]: I0918 13:10:45.562794 825 volume_manager.go:311] "Starting Kubelet Volume Manager"1255machine # [ 27.711514] k3s[825]: E0918 13:10:45.563126 825 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found"1256machine # [ 27.713520] k3s[825]: I0918 13:10:45.563927 825 desired_state_of_world_populator.go:146] "Desired state populator starts to run"1257machine # [ 27.715034] k3s[825]: I0918 13:10:45.564024 825 reconciler.go:29] "Reconciler: start to sync state"1258machine # [ 27.719891] k3s[825]: I0918 13:10:45.569677 825 factory.go:223] Registration of the systemd container factory successfully1259machine # [ 27.721511] k3s[825]: I0918 13:10:45.569832 825 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 directory1260machine # [ 27.724205] k3s[825]: I0918 13:10:45.583433 825 range_allocator.go:113] "No Secondary Service CIDR provided. Skipping filtering out secondary service addresses" logger="node-ipam-controller"1261machine # [ 27.726335] k3s[825]: I0918 13:10:45.583513 825 controllermanager.go:627] "Warning: controller is disabled" controller="service-lb-controller"1262machine # [ 27.728922] k3s[825]: E0918 13:10:45.598314 825 nodelease.go:50] "Failed to get node when trying to set owner ref to the node lease" err="nodes \"machine\" not found" node="machine"1263machine # [ 27.736368] k3s[825]: E0918 13:10:45.624581 825 kubelet.go:1661] "Image garbage collection failed once. Stats initialization may not have completed yet" err="invalid capacity 0 on image filesystem"1264machine # [ 27.740043] k3s[825]: I0918 13:10:45.627467 825 factory.go:223] Registration of the containerd container factory successfully1265machine # [ 27.775282] k3s[825]: E0918 13:10:45.663452 825 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found"1266machine # [ 27.852280] k3s[825]: I0918 13:10:45.740475 825 cpu_manager.go:225] "Starting" policy="none"1267machine # [ 27.853679] k3s[825]: I0918 13:10:45.741920 825 cpu_manager.go:226] "Reconciling" reconcilePeriod="10s"1268machine # [ 27.857170] k3s[825]: I0918 13:10:45.743359 825 state_mem.go:41] "Initialized" logger="CPUManager state checkpoint.CPUManager state memory"1269machine # [ 27.863308] k3s[825]: I0918 13:10:45.751032 825 policy_none.go:50] "Start"1270machine # [ 27.865243] k3s[825]: I0918 13:10:45.751071 825 memory_manager.go:187] "Starting memorymanager" policy="None"1271machine # [ 27.866938] k3s[825]: I0918 13:10:45.751092 825 state_mem.go:36] "Initializing new in-memory state store" logger="Memory Manager state checkpoint"1272machine # [ 27.872444] k3s[825]: I0918 13:10:45.755433 825 policy_none.go:44] "Start"1273machine # [ 27.891068] k3s[825]: E0918 13:10:45.779270 825 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found"1274machine # [ 27.940261] systemd[1]: Created slice libcontainer container kubepods.slice.1275machine # [ 27.964663] k3s[825]: I0918 13:10:45.852574 825 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv4"1276machine # [ 27.988144] k3s[825]: I0918 13:10:45.876176 825 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv6"1277machine # [ 27.989849] k3s[825]: I0918 13:10:45.876220 825 status_manager.go:249] "Starting to sync pod status with apiserver"1278machine # [ 27.991819] k3s[825]: I0918 13:10:45.876260 825 kubelet.go:2506] "Starting kubelet main sync loop"1279machine # [ 27.996532] k3s[825]: E0918 13:10:45.884756 825 kubelet.go:2530] "Skipping pod synchronization" err="[container runtime status check may not have completed yet, PLEG is not healthy: pleg has yet to be successful]"1280machine # [ 28.000608] k3s[825]: E0918 13:10:45.887411 825 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found"1281machine # [ 28.003774] systemd[1]: Created slice libcontainer container kubepods-burstable.slice.1282machine # [ 28.018372] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller"1283machine # [ 28.027526] systemd[1]: Created slice libcontainer container kubepods-besteffort.slice.1284machine # [ 28.030608] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Creating deploy event broadcaster"1285machine # Error from server (NotFound): namespaces "niks3" not found1286machine # [ 28.047007] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Starting /v1, Kind=Node controller"1287machine # [ 28.051824] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Creating helm-controller event broadcaster"1288machine # [ 28.062041] k3s[825]: I0918 13:10:45.950244 825 controller.go:667] quota admission added evaluator for: addons.k3s.cattle.io1289machine # [ 28.070957] k3s[825]: E0918 13:10:45.959166 825 manager.go:525] "Failed to read data from checkpoint" err="checkpoint is not found" checkpoint="kubelet_internal_checkpoint"1290machine # [ 28.073830] k3s[825]: I0918 13:10:45.962075 825 eviction_manager.go:194] "Eviction manager: starting control loop"1291machine # [ 28.075326] k3s[825]: I0918 13:10:45.963541 825 container_log_manager.go:146] "Initializing container log rotate workers" workers=1 monitorPeriod="10s"1292machine # [ 28.090721] k3s[825]: I0918 13:10:45.978938 825 plugin_manager.go:121] "Starting Kubelet Plugin Manager"1293machine # [ 28.098108] k3s[825]: E0918 13:10:45.986318 825 eviction_manager.go:272] "eviction manager: failed to check if we have separate container filesystem. Ignoring." err="no imagefs label for configured runtime"1294machine # [ 28.103719] k3s[825]: time="2026-09-18T13:10:45Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1295machine # [ 28.105419] k3s[825]: E0918 13:10:45.989193 825 eviction_manager.go:297] "Eviction manager: failed to get summary stats" err="failed to get node info: node \"machine\" not found"1296machine # [ 28.117152] k3s[825]: E0918 13:10:46.005228 825 csi_plugin.go:403] Failed to initialize CSINode: error updating CSINode annotation: timed out waiting for the condition; caused by: nodes "machine" not found1297machine # [ 28.136069] k3s[825]: time="2026-09-18T13:10:46Z" 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=Normal1298machine # [ 28.152535] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Cluster dns configmap has been set successfully"1299machine # [ 28.180477] k3s[825]: I0918 13:10:46.067199 825 kubelet_node_status.go:74] "Attempting to register node" node="machine"1300machine # [ 28.190922] k3s[825]: I0918 13:10:46.079102 825 kubelet_node_status.go:77] "Successfully registered node" node="machine"1301machine # [ 28.194330] k3s[825]: E0918 13:10:46.080858 825 kubelet_node_status.go:474] "Error updating node status, will retry" err="error getting node \"machine\": node \"machine\" not found"1302machine # [ 28.232098] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Annotations and labels have been set successfully on node: machine"1303machine # [ 28.233858] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Starting flannel with backend vxlan"1304machine # [ 28.341102] k3s[825]: I0918 13:10:46.228920 825 kubelet_node_status.go:427] "Fast updating node status as it just became ready"1305machine # [ 28.430029] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" object=kube-system/ccm reason=AppliedManifest type=Normal1306machine # [ 28.441772] k3s[825]: time="2026-09-18T13:10:46Z" 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=Normal1307machine # [ 28.449735] k3s[825]: I0918 13:10:46.337953 825 controllermanager.go:627] "Warning: controller is disabled" controller="bootstrap-signer-controller"1308machine # [ 28.455765] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Imported docker.io/library/niks3-server:1.4.0-aarch64-linux"1309machine # [ 28.460525] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Tagged docker.io/library/niks3-server@sha256:8ce208fff41efb8ed991f80aceaf8bbf8227738174eb251e6a21c28cfe355149"1310machine # [ 28.490241] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Imported 1 images from /var/lib/rancher/k3s/agent/images/niks3-server.tar in 1.0152008s"1311machine # [ 28.500367] k3s[825]: I0918 13:10:46.388465 825 node_lifecycle_controller.go:419] "Controller will reconcile labels" logger="node-lifecycle-controller"1312machine # [ 28.629859] k3s[825]: I0918 13:10:46.517753 825 apiserver.go:52] "Watching apiserver"1313machine # [ 28.812215] k3s[825]: I0918 13:10:46.698389 825 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="storageversion-garbage-collector-controller" requiredFeatureGates=["APIServerIdentity","StorageVersionAPI"]1314machine # [ 28.828351] k3s[825]: I0918 13:10:46.698478 825 controllermanager.go:579] "Warning: skipping controller" controller="storageversion-garbage-collector-controller"1315machine # [ 28.840565] k3s[825]: I0918 13:10:46.698511 825 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="device-taint-eviction-controller" requiredFeatureGates=["DynamicResourceAllocation","DRADeviceTaints"]1316machine # [ 28.851938] k3s[825]: I0918 13:10:46.698532 825 controllermanager.go:579] "Warning: skipping controller" controller="device-taint-eviction-controller"1317machine # [ 28.855975] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ci.yaml\"" object=kube-system/ci reason=AppliedManifest type=Normal1318machine # [ 28.863076] k3s[825]: time="2026-09-18T13:10:46Z" 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=Normal1319machine # [ 28.876217] k3s[825]: I0918 13:10:46.764341 825 desired_state_of_world_populator.go:154] "Finished populating initial desired state of world"1320machine # [ 29.087254] k3s[825]: time="2026-09-18T13:10:46Z" level=info msg="Labels and annotations have been set successfully on node: machine"1321machine # [ 29.150869] k3s[825]: I0918 13:10:47.039043 825 server.go:218] "Successfully retrieved NodeIPs" NodeIPs=["10.0.2.15","fec0::4c7f:95fe:5646:4f70"]1322machine # [ 29.153753] k3s[825]: E0918 13:10:47.041559 825 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`"1323machine # [ 29.206290] k3s[825]: I0918 13:10:47.094472 825 server.go:264] "kube-proxy running in dual-stack mode" primary ipFamily="IPv4"1324machine # [ 29.208542] k3s[825]: I0918 13:10:47.096788 825 server_linux.go:136] "Using iptables Proxier"1325machine # [ 29.227424] k3s[825]: I0918 13:10:47.115397 825 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"1326machine # [ 29.242974] k3s[825]: I0918 13:10:47.130795 825 serving.go:392] Generated self-signed cert in-memory1327machine # [ 29.273263] k3s[825]: I0918 13:10:47.161291 825 server.go:529] "Version info" version="v1.35.8+k3s1"1328machine # [ 29.274631] k3s[825]: I0918 13:10:47.161350 825 server.go:531] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1329machine # [ 29.293682] k3s[825]: I0918 13:10:47.181878 825 config.go:200] "Starting service config controller"1330machine # [ 29.295184] k3s[825]: I0918 13:10:47.183398 825 shared_informer.go:349] "Waiting for caches to sync" controller="service config"1331machine # [ 29.298765] k3s[825]: I0918 13:10:47.185452 825 config.go:106] "Starting endpoint slice config controller"1332machine # [ 29.300828] k3s[825]: I0918 13:10:47.185492 825 shared_informer.go:349] "Waiting for caches to sync" controller="endpoint slice config"1333machine # [ 29.303177] k3s[825]: I0918 13:10:47.185518 825 config.go:403] "Starting serviceCIDR config controller"1334machine # [ 29.305545] k3s[825]: I0918 13:10:47.185527 825 shared_informer.go:349] "Waiting for caches to sync" controller="serviceCIDR config"1335machine # [ 29.307659] k3s[825]: I0918 13:10:47.186191 825 config.go:309] "Starting node config controller"1336machine # [ 29.309166] k3s[825]: I0918 13:10:47.186204 825 shared_informer.go:349] "Waiting for caches to sync" controller="node config"1337machine # [ 29.311341] k3s[825]: I0918 13:10:47.186214 825 shared_informer.go:356] "Caches are synced" controller="node config"1338machine # [ 29.360834] k3s[825]: I0918 13:10:47.248784 825 controller.go:667] quota admission added evaluator for: deployments.apps1339machine # Error from server (NotFound): namespaces "niks3" not found1340machine # [ 29.415594] k3s[825]: time="2026-09-18T13:10:47Z" level=info msg="Starting rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding controller"1341machine # [ 29.424032] k3s[825]: time="2026-09-18T13:10:47Z" level=info msg="Starting batch/v1, Kind=Job controller"1342machine # [ 29.425309] k3s[825]: time="2026-09-18T13:10:47Z" level=info msg="Starting /v1, Kind=ConfigMap controller"1343machine # [ 29.426545] k3s[825]: time="2026-09-18T13:10:47Z" level=info msg="Starting /v1, Kind=ServiceAccount controller"1344machine # [ 29.427831] k3s[825]: time="2026-09-18T13:10:47Z" level=info msg="Starting /v1, Kind=Secret controller"1345machine # [ 29.429191] k3s[825]: time="2026-09-18T13:10:47Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller"1346machine # [ 29.430595] k3s[825]: time="2026-09-18T13:10:47Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller"1347machine # [ 29.599946] k3s[825]: I0918 13:10:47.488132 825 serving.go:392] Generated self-signed cert in-memory1348machine # [ 29.616106] k3s[825]: I0918 13:10:47.502398 825 shared_informer.go:356] "Caches are synced" controller="service config"1349machine # [ 29.624034] k3s[825]: I0918 13:10:47.511052 825 alloc.go:329] "allocated clusterIPs" service="kube-system/kube-dns" clusterIPs={"IPv4":"10.43.0.10"}1350machine # [ 29.628030] k3s[825]: time="2026-09-18T13:10:47Z" 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=Normal1351machine # [ 29.699624] k3s[825]: I0918 13:10:47.587142 825 shared_informer.go:356] "Caches are synced" controller="endpoint slice config"1352machine # [ 29.706252] k3s[825]: I0918 13:10:47.594447 825 shared_informer.go:356] "Caches are synced" controller="serviceCIDR config"1353machine # [ 29.852179] k3s[825]: I0918 13:10:47.736457 825 controllermanager.go:160] Version: v1.35.8+k3s11354machine # [ 29.854712] k3s[825]: I0918 13:10:47.742935 825 secure_serving.go:211] Serving securely on 127.0.0.1:102581355machine # [ 29.856708] k3s[825]: I0918 13:10:47.744944 825 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1356machine # [ 29.858412] k3s[825]: I0918 13:10:47.746650 825 shared_informer.go:370] "Waiting for caches to sync"1357machine # [ 29.859702] k3s[825]: I0918 13:10:47.747949 825 tlsconfig.go:243] "Starting DynamicServingCertificateController"1358machine # [ 29.864175] k3s[825]: I0918 13:10:47.749838 825 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1359machine # [ 29.866281] k3s[825]: I0918 13:10:47.749880 825 shared_informer.go:370] "Waiting for caches to sync"1360machine # [ 29.867506] k3s[825]: I0918 13:10:47.749900 825 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1361machine # [ 29.872111] k3s[825]: I0918 13:10:47.749912 825 shared_informer.go:370] "Waiting for caches to sync"1362machine # [ 29.876818] k3s[825]: time="2026-09-18T13:10:47Z" level=info msg="Creating service-lb-controller event broadcaster"1363machine # [ 29.999409] k3s[825]: I0918 13:10:47.887566 825 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="podcertificaterequest-cleaner-controller" requiredFeatureGates=["PodCertificateRequest"]1364machine # [ 30.002275] k3s[825]: I0918 13:10:47.887624 825 controllermanager.go:579] "Warning: skipping controller" controller="podcertificaterequest-cleaner-controller"1365machine # [ 30.160775] k3s[825]: I0918 13:10:48.048362 825 shared_informer.go:377] "Caches are synced"1366machine # [ 30.162627] k3s[825]: I0918 13:10:48.050724 825 shared_informer.go:377] "Caches are synced"1367machine # [ 30.163951] k3s[825]: I0918 13:10:48.050776 825 shared_informer.go:377] "Caches are synced"1368machine # [ 30.362787] k3s[825]: time="2026-09-18T13:10:48Z" level=info msg="Starting /v1, Kind=Node controller"1369machine # [ 30.370978] k3s[825]: time="2026-09-18T13:10:48Z" level=info msg="Starting /v1, Kind=Pod controller"1370machine # [ 30.378640] k3s[825]: time="2026-09-18T13:10:48Z" level=info msg="Starting apps/v1, Kind=DaemonSet controller"1371machine # [ 30.386900] k3s[825]: I0918 13:10:48.275071 825 controllermanager.go:329] Started "cloud-node-lifecycle-controller"1372machine # [ 30.389745] k3s[825]: time="2026-09-18T13:10:48Z" level=info msg="Starting discovery.k8s.io/v1, Kind=EndpointSlice controller"1373machine # [ 30.392622] k3s[825]: I0918 13:10:48.276019 825 node_lifecycle_controller.go:112] Sending events to api server1374machine # [ 30.395137] k3s[825]: I0918 13:10:48.276222 825 controllermanager.go:329] Started "service-lb-controller"1375machine # [ 30.397718] k3s[825]: W0918 13:10:48.276242 825 controllermanager.go:306] "node-route-controller" is disabled1376machine # [ 30.402086] k3s[825]: I0918 13:10:48.279949 825 controllermanager.go:329] Started "cloud-node-controller"1377machine # [ 30.405296] k3s[825]: I0918 13:10:48.281013 825 node_controller.go:176] Sending events to api server.1378machine # [ 30.408121] k3s[825]: I0918 13:10:48.281075 825 controller.go:235] Starting service controller1379machine # [ 30.420328] k3s[825]: I0918 13:10:48.281105 825 shared_informer.go:370] "Waiting for caches to sync"1380machine # [ 30.422405] k3s[825]: I0918 13:10:48.281195 825 node_controller.go:185] Waiting for informer caches to sync1381machine # [ 30.425473] k3s[825]: time="2026-09-18T13:10:48Z" 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=Normal1382machine # [ 30.432101] k3s[825]: time="2026-09-18T13:10:48Z" 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=Normal1383machine # [ 30.463896] k3s[825]: I0918 13:10:48.351011 825 expand_controller.go:328] "Starting expand controller"1384machine # [ 30.465670] k3s[825]: I0918 13:10:48.351051 825 shared_informer.go:370] "Waiting for caches to sync"1385machine # [ 30.467143] k3s[825]: I0918 13:10:48.351273 825 shared_informer.go:370] "Waiting for caches to sync"1386machine # [ 30.469616] k3s[825]: I0918 13:10:48.351342 825 endpoints_controller.go:193] "Starting endpoint controller"1387machine # [ 30.471275] k3s[825]: I0918 13:10:48.351354 825 shared_informer.go:370] "Waiting for caches to sync"1388machine # [ 30.475404] k3s[825]: I0918 13:10:48.351375 825 namespace_controller.go:202] "Starting namespace controller"1389machine # [ 30.477065] k3s[825]: I0918 13:10:48.351387 825 shared_informer.go:370] "Waiting for caches to sync"1390machine # [ 30.478453] k3s[825]: I0918 13:10:48.351416 825 serviceaccounts_controller.go:117] "Starting service account controller"1391machine # [ 30.480175] k3s[825]: I0918 13:10:48.351429 825 shared_informer.go:370] "Waiting for caches to sync"1392machine # [ 30.481516] k3s[825]: I0918 13:10:48.351450 825 disruption.go:458] "Sending events to api server."1393machine # [ 30.482822] k3s[825]: I0918 13:10:48.351477 825 disruption.go:465] "Starting disruption controller"1394machine # [ 30.484261] k3s[825]: I0918 13:10:48.351487 825 shared_informer.go:370] "Waiting for caches to sync"1395machine # [ 30.485543] k3s[825]: I0918 13:10:48.351517 825 ttl_controller.go:127] "Starting TTL controller"1396machine # [ 30.486776] k3s[825]: I0918 13:10:48.351531 825 shared_informer.go:370] "Waiting for caches to sync"1397machine # [ 30.488071] k3s[825]: I0918 13:10:48.351548 825 ttlafterfinished_controller.go:112] "Starting TTL after finished controller"1398machine # [ 30.489560] k3s[825]: I0918 13:10:48.351560 825 shared_informer.go:370] "Waiting for caches to sync"1399machine # [ 30.490907] k3s[825]: I0918 13:10:48.351606 825 pv_controller_base.go:307] "Starting persistent volume controller"1400machine # [ 30.492356] k3s[825]: I0918 13:10:48.351620 825 shared_informer.go:370] "Waiting for caches to sync"1401machine # [ 30.493554] k3s[825]: I0918 13:10:48.351686 825 servicecidrs_controller.go:136] "Starting" controller="service-cidr-controller"1402machine # [ 30.495824] k3s[825]: I0918 13:10:48.351702 825 shared_informer.go:370] "Waiting for caches to sync"1403machine # [ 30.497203] k3s[825]: I0918 13:10:48.351782 825 replica_set.go:241] "Starting controller" name="replicaset"1404machine # [ 30.498458] k3s[825]: I0918 13:10:48.351796 825 shared_informer.go:370] "Waiting for caches to sync"1405machine # [ 30.499655] k3s[825]: I0918 13:10:48.351851 825 endpointslicemirroring_controller.go:226] "Starting EndpointSliceMirroring controller"1406machine # [ 30.501351] k3s[825]: I0918 13:10:48.351862 825 shared_informer.go:370] "Waiting for caches to sync"1407machine # [ 30.502629] k3s[825]: I0918 13:10:48.352159 825 deployment_controller.go:172] "Starting controller" controller="deployment"1408machine # [ 30.504057] k3s[825]: I0918 13:10:48.352175 825 shared_informer.go:370] "Waiting for caches to sync"1409machine # [ 30.505243] k3s[825]: I0918 13:10:48.352218 825 cleaner.go:83] "Starting CSR cleaner controller"1410machine # [ 30.506418] k3s[825]: I0918 13:10:48.352274 825 taint_eviction.go:283] "Starting" controller="taint-eviction-controller"1411machine # [ 30.507924] k3s[825]: I0918 13:10:48.360470 825 daemon_controller.go:309] "Starting daemon sets controller"1412machine # [ 30.511452] k3s[825]: I0918 13:10:48.360504 825 shared_informer.go:370] "Waiting for caches to sync"1413machine # [ 30.512819] k3s[825]: I0918 13:10:48.360548 825 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-legacy-unknown"1414machine # [ 30.514501] k3s[825]: I0918 13:10:48.360561 825 shared_informer.go:370] "Waiting for caches to sync"1415machine # [ 30.515720] k3s[825]: I0918 13:10:48.360583 825 vac_protection_controller.go:206] "Starting VAC protection controller"1416machine # [ 30.517383] k3s[825]: I0918 13:10:48.360594 825 shared_informer.go:370] "Waiting for caches to sync"1417machine # [ 30.518698] k3s[825]: I0918 13:10:48.360650 825 replica_set.go:241] "Starting controller" name="replicationcontroller"1418machine # [ 30.520144] k3s[825]: I0918 13:10:48.360661 825 shared_informer.go:370] "Waiting for caches to sync"1419machine # [ 30.521368] k3s[825]: I0918 13:10:48.360707 825 stateful_set.go:180] "Starting stateful set controller"1420machine # [ 30.522598] k3s[825]: I0918 13:10:48.360718 825 shared_informer.go:370] "Waiting for caches to sync"1421machine # [ 30.523929] k3s[825]: I0918 13:10:48.360803 825 node_ipam_controller.go:142] "Starting ipam controller"1422machine # [ 30.525289] k3s[825]: I0918 13:10:48.360818 825 shared_informer.go:370] "Waiting for caches to sync"1423machine # [ 30.526541] k3s[825]: I0918 13:10:48.360841 825 clusterroleaggregation_controller.go:194] "Starting ClusterRoleAggregator controller"1424machine # [ 30.528160] k3s[825]: I0918 13:10:48.360854 825 shared_informer.go:370] "Waiting for caches to sync"1425machine # [ 30.529466] k3s[825]: I0918 13:10:48.360876 825 pvc_protection_controller.go:166] "Starting PVC protection controller"1426machine # [ 30.530859] k3s[825]: I0918 13:10:48.360888 825 shared_informer.go:370] "Waiting for caches to sync"1427machine # [ 30.532113] k3s[825]: I0918 13:10:48.360910 825 controller.go:174] "Starting ephemeral volume controller"1428machine # [ 30.533382] k3s[825]: I0918 13:10:48.360921 825 shared_informer.go:370] "Waiting for caches to sync"1429machine # [ 30.534727] k3s[825]: I0918 13:10:48.360966 825 endpointslice_controller.go:283] "Starting endpoint slice controller"1430machine # [ 30.536166] k3s[825]: I0918 13:10:48.360998 825 shared_informer.go:370] "Waiting for caches to sync"1431machine # [ 30.537387] k3s[825]: I0918 13:10:48.361138 825 node_lifecycle_controller.go:453] "Sending events to api server"1432machine # [ 30.538709] k3s[825]: I0918 13:10:48.362808 825 node_lifecycle_controller.go:460] "Starting node controller"1433machine # [ 30.540087] k3s[825]: I0918 13:10:48.362834 825 shared_informer.go:370] "Waiting for caches to sync"1434machine # [ 30.541293] k3s[825]: I0918 13:10:48.362876 825 pv_protection_controller.go:81] "Starting PV protection controller"1435machine # [ 30.542654] k3s[825]: I0918 13:10:48.362888 825 shared_informer.go:370] "Waiting for caches to sync"1436machine # [ 30.543873] k3s[825]: I0918 13:10:48.362912 825 publisher.go:107] "Starting root CA cert publisher controller"1437machine # [ 30.545334] k3s[825]: I0918 13:10:48.362922 825 shared_informer.go:370] "Waiting for caches to sync"1438machine # [ 30.546549] k3s[825]: I0918 13:10:48.362973 825 cronjob_controllerv2.go:143] "Starting cronjob controller v2"1439machine # [ 30.547856] k3s[825]: I0918 13:10:48.362985 825 shared_informer.go:370] "Waiting for caches to sync"1440machine # [ 30.549173] k3s[825]: I0918 13:10:48.363051 825 controller.go:423] "Starting resource claim controller"1441machine # [ 30.550470] k3s[825]: I0918 13:10:48.363062 825 shared_informer.go:370] "Waiting for caches to sync"1442machine # [ 30.551684] k3s[825]: I0918 13:10:48.363085 825 legacy_serviceaccount_token_cleaner.go:103] "Starting legacy service account token cleaner controller"1443machine # [ 30.553546] k3s[825]: I0918 13:10:48.363123 825 shared_informer.go:370] "Waiting for caches to sync"1444machine # [ 30.554769] k3s[825]: I0918 13:10:48.363141 825 shared_informer.go:370] "Waiting for caches to sync"1445machine # [ 30.556081] k3s[825]: I0918 13:10:48.363165 825 gc_controller.go:98] "Starting GC controller"1446machine # [ 30.557224] k3s[825]: I0918 13:10:48.363176 825 shared_informer.go:370] "Waiting for caches to sync"1447machine # [ 30.558437] k3s[825]: I0918 13:10:48.363240 825 job_controller.go:254] "Starting job controller"1448machine # [ 30.559613] k3s[825]: I0918 13:10:48.363251 825 shared_informer.go:370] "Waiting for caches to sync"1449machine # [ 30.560922] k3s[825]: I0918 13:10:48.363320 825 certificate_controller.go:120] "Starting certificate controller" name="csrapproving"1450machine # [ 30.562476] k3s[825]: I0918 13:10:48.363331 825 shared_informer.go:370] "Waiting for caches to sync"1451machine # [ 30.563690] k3s[825]: I0918 13:10:48.363347 825 tokencleaner.go:117] "Starting token cleaner controller"1452machine # [ 30.568242] k3s[825]: I0918 13:10:48.363357 825 shared_informer.go:370] "Waiting for caches to sync"1453machine # [ 30.569493] k3s[825]: I0918 13:10:48.363401 825 attach_detach_controller.go:335] "Starting attach detach controller"1454machine # [ 30.570845] k3s[825]: I0918 13:10:48.363413 825 shared_informer.go:370] "Waiting for caches to sync"1455machine # [ 30.576209] k3s[825]: I0918 13:10:48.363567 825 resource_quota_controller.go:297] "Starting resource quota controller"1456machine # [ 30.577635] k3s[825]: I0918 13:10:48.363579 825 shared_informer.go:370] "Waiting for caches to sync"1457machine # [ 30.578855] k3s[825]: I0918 13:10:48.368450 825 taint_eviction.go:288] "Sending events to API server"1458machine # [ 30.580120] k3s[825]: I0918 13:10:48.368486 825 shared_informer.go:370] "Waiting for caches to sync"1459machine # [ 30.581328] k3s[825]: I0918 13:10:48.368615 825 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-serving"1460machine # [ 30.584135] k3s[825]: I0918 13:10:48.368635 825 shared_informer.go:370] "Waiting for caches to sync"1461machine # [ 30.585362] k3s[825]: I0918 13:10:48.368654 825 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-client"1462machine # [ 30.592123] k3s[825]: I0918 13:10:48.368664 825 shared_informer.go:370] "Waiting for caches to sync"1463machine # [ 30.593427] k3s[825]: I0918 13:10:48.368684 825 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kube-apiserver-client"1464machine # [ 30.595189] k3s[825]: I0918 13:10:48.368696 825 shared_informer.go:370] "Waiting for caches to sync"1465machine # [ 30.596515] k3s[825]: I0918 13:10:48.368718 825 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"1466machine # [ 30.604105] k3s[825]: I0918 13:10:48.368935 825 garbagecollector.go:141] "Starting controller" controller="garbagecollector"1467machine # [ 30.605668] k3s[825]: I0918 13:10:48.368953 825 shared_informer.go:370] "Waiting for caches to sync"1468machine # [ 30.606870] k3s[825]: I0918 13:10:48.368989 825 horizontal.go:204] "Starting HPA controller"1469machine # [ 30.608027] k3s[825]: I0918 13:10:48.369000 825 shared_informer.go:370] "Waiting for caches to sync"1470machine # [ 30.609282] k3s[825]: I0918 13:10:48.369020 825 resource_quota_monitor.go:309] "QuotaMonitor running"1471machine # [ 30.610472] k3s[825]: I0918 13:10:48.369192 825 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"1472machine # [ 30.616163] k3s[825]: I0918 13:10:48.369290 825 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"1473machine # [ 30.618708] k3s[825]: I0918 13:10:48.369356 825 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"1474machine # [ 30.623309] k3s[825]: I0918 13:10:48.369655 825 graph_builder.go:386] "Running" component="GraphBuilder"1475machine # [ 30.628128] k3s[825]: I0918 13:10:48.379916 825 shared_informer.go:370] "Waiting for caches to sync"1476machine # [ 30.629388] k3s[825]: I0918 13:10:48.394763 825 node_controller.go:429] Initializing node machine with cloud provider1477machine # [ 30.630767] k3s[825]: I0918 13:10:48.428138 825 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"1478machine # [ 30.636194] k3s[825]: I0918 13:10:48.456516 825 shared_informer.go:377] "Caches are synced"1479machine # [ 30.637324] k3s[825]: I0918 13:10:48.462389 825 controller.go:667] quota admission added evaluator for: helmcharts.helm.cattle.io1480machine # [ 30.638886] k3s[825]: I0918 13:10:48.465617 825 shared_informer.go:377] "Caches are synced"1481machine # [ 30.644069] k3s[825]: I0918 13:10:48.465654 825 range_allocator.go:177] "Sending events to api server"1482machine # [ 30.646617] k3s[825]: I0918 13:10:48.465675 825 range_allocator.go:181] "Starting range CIDR allocator"1483machine # [ 30.647891] k3s[825]: I0918 13:10:48.465681 825 shared_informer.go:370] "Waiting for caches to sync"1484machine # [ 30.649504] k3s[825]: I0918 13:10:48.465687 825 shared_informer.go:377] "Caches are synced"1485machine # [ 30.650635] k3s[825]: I0918 13:10:48.482443 825 node_controller.go:474] Successfully initialized node machine with cloud provider1486machine # [ 30.652197] k3s[825]: I0918 13:10:48.483486 825 event.go:389] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="v1" type="Normal" reason="Synced" message="Node synced successfully"1487machine # [ 30.655821] k3s[825]: I0918 13:10:48.488210 825 shared_informer.go:377] "Caches are synced"1488machine # [ 30.657502] k3s[825]: time="2026-09-18T13:10:48Z" 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=Normal1489machine # [ 30.662748] k3s[825]: time="2026-09-18T13:10:48Z" level=info msg="Synced coredns NodeHosts entries for machine"1490machine # [ 30.665057] k3s[825]: I0918 13:10:48.550490 825 server.go:173] "Starting Kubernetes Scheduler" version="v1.35.8+k3s1"1491machine # [ 30.667485] k3s[825]: I0918 13:10:48.550520 825 server.go:175] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1492machine # [ 30.675233] k3s[825]: I0918 13:10:48.563427 825 shared_informer.go:377] "Caches are synced"1493machine # [ 30.678666] k3s[825]: I0918 13:10:48.563766 825 shared_informer.go:377] "Caches are synced"1494machine # [ 30.679822] k3s[825]: I0918 13:10:48.563791 825 shared_informer.go:377] "Caches are synced"1495machine # [ 30.681050] k3s[825]: I0918 13:10:48.563821 825 shared_informer.go:377] "Caches are synced"1496machine # [ 30.682264] k3s[825]: I0918 13:10:48.564423 825 shared_informer.go:377] "Caches are synced"1497machine # [ 30.683394] k3s[825]: I0918 13:10:48.564458 825 shared_informer.go:377] "Caches are synced"1498machine # [ 30.688150] k3s[825]: I0918 13:10:48.564485 825 shared_informer.go:377] "Caches are synced"1499machine # [ 30.689289] k3s[825]: I0918 13:10:48.564555 825 node_lifecycle_controller.go:1234] "Initializing eviction metric for zone" zone=""1500machine # [ 30.690838] k3s[825]: I0918 13:10:48.564629 825 node_lifecycle_controller.go:886] "Missing timestamp for Node. Assuming now as a timestamp" node="machine"1501machine # [ 30.692765] k3s[825]: I0918 13:10:48.564662 825 node_lifecycle_controller.go:1080] "Controller detected that zone is now in new state" zone="" newState="Normal"1502machine # [ 30.694602] k3s[825]: I0918 13:10:48.564693 825 shared_informer.go:377] "Caches are synced"1503machine # [ 30.695726] k3s[825]: I0918 13:10:48.564709 825 shared_informer.go:377] "Caches are synced"1504machine # [ 30.700117] k3s[825]: I0918 13:10:48.564739 825 shared_informer.go:377] "Caches are synced"1505machine # [ 30.701268] k3s[825]: I0918 13:10:48.564762 825 shared_informer.go:377] "Caches are synced"1506machine # [ 30.702459] k3s[825]: I0918 13:10:48.575222 825 shared_informer.go:377] "Caches are synced"1507machine # [ 30.703702] k3s[825]: I0918 13:10:48.575287 825 shared_informer.go:377] "Caches are synced"1508machine # [ 30.727453] k3s[825]: I0918 13:10:48.615668 825 range_allocator.go:433] "Set node PodCIDR" node="machine" podCIDRs=["10.42.0.0/24"]1509machine # [ 30.737316] k3s[825]: I0918 13:10:48.625529 825 shared_informer.go:370] "Waiting for caches to sync"1510machine # [ 30.754288] k3s[825]: I0918 13:10:48.642481 825 secure_serving.go:211] Serving securely on 127.0.0.1:102591511machine # [ 30.760131] k3s[825]: I0918 13:10:48.646426 825 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1512machine # [ 30.761621] k3s[825]: I0918 13:10:48.646465 825 shared_informer.go:370] "Waiting for caches to sync"1513machine # [ 30.762854] k3s[825]: I0918 13:10:48.646496 825 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"1514machine # [ 30.765829] k3s[825]: I0918 13:10:48.646628 825 tlsconfig.go:243] "Starting DynamicServingCertificateController"1515machine # [ 30.767179] k3s[825]: I0918 13:10:48.649603 825 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1516machine # [ 30.772217] k3s[825]: I0918 13:10:48.649629 825 shared_informer.go:370] "Waiting for caches to sync"1517machine # [ 30.773439] k3s[825]: I0918 13:10:48.649649 825 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1518machine # [ 30.775661] k3s[825]: I0918 13:10:48.649661 825 shared_informer.go:370] "Waiting for caches to sync"1519machine # [ 30.776992] k3s[825]: I0918 13:10:48.651387 825 shared_informer.go:377] "Caches are synced"1520machine # [ 30.778113] k3s[825]: I0918 13:10:48.651420 825 shared_informer.go:377] "Caches are synced"1521machine # [ 30.779231] k3s[825]: I0918 13:10:48.651724 825 shared_informer.go:377] "Caches are synced"1522machine # [ 30.784098] k3s[825]: I0918 13:10:48.651908 825 shared_informer.go:377] "Caches are synced"1523machine # [ 30.785271] k3s[825]: I0918 13:10:48.652198 825 shared_informer.go:377] "Caches are synced"1524machine # [ 30.786425] k3s[825]: I0918 13:10:48.656945 825 shared_informer.go:377] "Caches are synced"1525machine # [ 30.787568] k3s[825]: time="2026-09-18T13:10:48Z" 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=Normal1526machine # [ 30.793474] k3s[825]: I0918 13:10:48.660560 825 shared_informer.go:377] "Caches are synced"1527machine # [ 30.794748] k3s[825]: I0918 13:10:48.660592 825 shared_informer.go:377] "Caches are synced"1528machine # [ 30.795893] k3s[825]: I0918 13:10:48.660758 825 shared_informer.go:377] "Caches are synced"1529machine # [ 30.797566] k3s[825]: I0918 13:10:48.661022 825 shared_informer.go:377] "Caches are synced"1530machine # [ 30.798684] k3s[825]: I0918 13:10:48.668695 825 shared_informer.go:377] "Caches are synced"1531machine # [ 30.799802] k3s[825]: I0918 13:10:48.668747 825 shared_informer.go:377] "Caches are synced"1532machine # [ 30.804138] k3s[825]: I0918 13:10:48.673541 825 shared_informer.go:377] "Caches are synced"1533machine # [ 30.805308] k3s[825]: I0918 13:10:48.673589 825 shared_informer.go:377] "Caches are synced"1534machine # Error from server (NotFound): namespaces "niks3" not found1535machine # [ 30.812162] k3s[825]: I0918 13:10:48.673616 825 shared_informer.go:377] "Caches are synced"1536machine # [ 30.813313] k3s[825]: I0918 13:10:48.674574 825 shared_informer.go:377] "Caches are synced"1537machine # [ 30.814424] k3s[825]: I0918 13:10:48.679979 825 shared_informer.go:377] "Caches are synced"1538machine # [ 30.864078] k3s[825]: I0918 13:10:48.751773 825 shared_informer.go:377] "Caches are synced"1539machine # [ 30.865305] k3s[825]: I0918 13:10:48.751948 825 shared_informer.go:377] "Caches are synced"1540machine # [ 30.868046] k3s[825]: I0918 13:10:48.755929 825 shared_informer.go:377] "Caches are synced"1541machine # [ 30.869214] k3s[825]: I0918 13:10:48.756152 825 shared_informer.go:377] "Caches are synced"1542machine # [ 30.870372] k3s[825]: I0918 13:10:48.757124 825 shared_informer.go:377] "Caches are synced"1543machine # [ 30.896087] k3s[825]: I0918 13:10:48.783679 825 shared_informer.go:377] "Caches are synced"1544machine # [ 30.897333] k3s[825]: I0918 13:10:48.783743 825 shared_informer.go:377] "Caches are synced"1545machine # [ 30.898427] k3s[825]: I0918 13:10:48.783838 825 shared_informer.go:377] "Caches are synced"1546machine # [ 30.899541] k3s[825]: I0918 13:10:48.783978 825 shared_informer.go:377] "Caches are synced"1547machine # [ 30.904113] k3s[825]: I0918 13:10:48.784165 825 shared_informer.go:377] "Caches are synced"1548machine # [ 30.960737] k3s[825]: time="2026-09-18T13:10:48Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Deferred node password secret validation complete" object=machine reason=NodePasswordValidationComplete type=Normal1549machine # [ 30.989551] k3s[825]: time="2026-09-18T13:10:48Z" 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=Normal1550machine # [ 31.024100] k3s[825]: I0918 13:10:48.912280 825 controller.go:667] quota admission added evaluator for: jobs.batch1551machine # [ 31.058883] k3s[825]: I0918 13:10:48.947010 825 shared_informer.go:377] "Caches are synced"1552machine # [ 31.062522] k3s[825]: I0918 13:10:48.950130 825 shared_informer.go:377] "Caches are synced"1553machine # [ 31.063912] k3s[825]: I0918 13:10:48.950178 825 shared_informer.go:377] "Caches are synced"1554machine # [ 31.088110] k3s[825]: time="2026-09-18T13:10:48Z" 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=Normal1555machine # [ 31.096100] k3s[825]: time="2026-09-18T13:10:48Z" 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=Normal1556machine # [ 31.218741] k3s[825]: I0918 13:10:49.105740 825 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161557machine # [ 31.226403] k3s[825]: I0918 13:10:49.114081 825 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161558machine # [ 31.261937] k3s[825]: I0918 13:10:49.149430 825 controller.go:667] quota admission added evaluator for: replicasets.apps1559machine # [ 31.294862] k3s[825]: time="2026-09-18T13:10:49Z" 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=Normal1560machine # [ 31.398608] k3s[825]: time="2026-09-18T13:10:49Z" level=info msg="Flannel found PodCIDR assigned for node machine"1561machine # [ 31.405113] k3s[825]: time="2026-09-18T13:10:49Z" 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=Normal1562machine # [ 31.421835] k3s[825]: time="2026-09-18T13:10:49Z" level=info msg="The interface eth0 with ipv4 address 10.0.2.15 will be used by flannel"1563machine # [ 31.425855] k3s[825]: I0918 13:10:49.305870 825 kube.go:139] Waiting 10m0s for node controller to sync1564machine # [ 31.428456] k3s[825]: I0918 13:10:49.305977 825 kube.go:537] Starting kube subnet manager1565machine # [ 31.656151] k3s[825]: time="2026-09-18T13:10:49Z" 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=Normal1566machine # [ 31.814717] k3s[825]: time="2026-09-18T13:10:49Z" level=info msg="Tunnel authorizer set Kubelet Port 0.0.0.0:10250"1567machine # Error from server (NotFound): namespaces "niks3" not found1568machine # [ 32.421344] k3s[825]: I0918 13:10:50.307556 825 kube.go:163] Node controller sync successful1569machine # [ 32.428331] k3s[825]: I0918 13:10:50.307830 825 vxlan.go:128] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false1570machine # [ 32.440354] k3s[825]: I0918 13:10:50.325832 825 shared_informer.go:377] "Caches are synced"1571machine # [ 32.449937] k3s[825]: I0918 13:10:50.338041 825 kube.go:704] List of node(machine) annotations: map[string]string{"alpha.kubernetes.io/provided-node-ip":"10.0.2.15,fec0::4c7f:95fe:5646:4f70", "k3s.io/hostname":"machine", "k3s.io/internal-ip":"10.0.2.15,fec0::4c7f:95fe:5646:4f70", "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"}1572machine # [ 32.481816] k3s[825]: I0918 13:10:50.369878 825 shared_informer.go:377] "Caches are synced"1573machine # [ 32.483923] k3s[825]: I0918 13:10:50.372159 825 garbagecollector.go:166] "Garbage collector: all resource monitors have synced"1574machine # [ 32.488820] k3s[825]: I0918 13:10:50.377022 825 garbagecollector.go:169] "Proceeding to collect garbage"1575machine # [ 32.508068] (udev-worker)[1081]: Network interface NamePolicy= disabled on kernel command line.1576machine # [ 32.537349] systemd[1]: Created slice libcontainer container kubepods-burstable-poda4777e0f_1e25_4426_81e9_c06bf6ccaeed.slice.1577machine # [ 32.547317] k3s[825]: time="2026-09-18T13:10:50Z" level=info msg="Adding node OwnerReference to node-password secret machine.node-password.k3s"1578machine # [ 32.551721] k3s[825]: I0918 13:10:50.439944 825 iptables.go:50] Starting flannel in iptables mode...1579machine # [ 32.554330] k3s[825]: time="2026-09-18T13:10:50Z" level=warning msg="no subnet found for key: FLANNEL_NETWORK in file: /run/flannel/subnet.env"1580machine # [ 32.556707] k3s[825]: time="2026-09-18T13:10:50Z" level=warning msg="no subnet found for key: FLANNEL_SUBNET in file: /run/flannel/subnet.env"1581machine # [ 32.558807] k3s[825]: time="2026-09-18T13:10:50Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_NETWORK in file: /run/flannel/subnet.env"1582machine # [ 32.561124] k3s[825]: time="2026-09-18T13:10:50Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_SUBNET in file: /run/flannel/subnet.env"1583machine # [ 32.568113] k3s[825]: I0918 13:10:50.441459 825 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 rules1584machine # [ 32.570784] k3s[825]: I0918 13:10:50.454895 825 kube.go:558] Creating the node lease for IPv4. This is the n.Spec.PodCIDRs: [10.42.0.0/24]1585machine # [ 32.579681] systemd[1]: Created slice libcontainer container kubepods-burstable-pod3edefd55_a25b_415a_b729_95e5d37412a0.slice.1586machine # [ 32.596132] dhcpcd[612]: flannel.1: IAID dd:f9:a9:021587machine # [ 32.597042] dhcpcd[612]: flannel.1: adding address fe80::b073:ddff:fef9:a9021588machine # [ 32.598102] k3s[825]: I0918 13:10:50.484133 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"content\" (UniqueName: \"kubernetes.io/configmap/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-content\") pod \"helm-install-niks3-7snlh\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") " pod="kube-system/helm-install-niks3-7snlh"1589machine # [ 32.602507] k3s[825]: I0918 13:10:50.484190 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-6fw8r\" (UniqueName: \"kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-kube-api-access-6fw8r\") pod \"helm-install-niks3-7snlh\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") " pod="kube-system/helm-install-niks3-7snlh"1590machine # [ 32.607247] k3s[825]: I0918 13:10:50.484255 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"config-volume\" (UniqueName: \"kubernetes.io/configmap/3edefd55-a25b-415a-b729-95e5d37412a0-config-volume\") pod \"coredns-c5fdd76cf-n7qs8\" (UID: \"3edefd55-a25b-415a-b729-95e5d37412a0\") " pod="kube-system/coredns-c5fdd76cf-n7qs8"1591machine # [ 32.612069] k3s[825]: I0918 13:10:50.484277 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-cache\") pod \"helm-install-niks3-7snlh\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") " pod="kube-system/helm-install-niks3-7snlh"1592machine # [ 32.616467] k3s[825]: I0918 13:10:50.484406 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-config\") pod \"helm-install-niks3-7snlh\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") " pod="kube-system/helm-install-niks3-7snlh"1593machine # [ 32.620879] k3s[825]: I0918 13:10:50.484428 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"custom-config-volume\" (UniqueName: \"kubernetes.io/configmap/3edefd55-a25b-415a-b729-95e5d37412a0-custom-config-volume\") pod \"coredns-c5fdd76cf-n7qs8\" (UID: \"3edefd55-a25b-415a-b729-95e5d37412a0\") " pod="kube-system/coredns-c5fdd76cf-n7qs8"1594machine # [ 32.625435] k3s[825]: I0918 13:10:50.484446 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-slk7d\" (UniqueName: \"kubernetes.io/projected/3edefd55-a25b-415a-b729-95e5d37412a0-kube-api-access-slk7d\") pod \"coredns-c5fdd76cf-n7qs8\" (UID: \"3edefd55-a25b-415a-b729-95e5d37412a0\") " pod="kube-system/coredns-c5fdd76cf-n7qs8"1595machine # [ 32.630101] k3s[825]: I0918 13:10:50.484464 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-helm\") pod \"helm-install-niks3-7snlh\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") " pod="kube-system/helm-install-niks3-7snlh"1596machine # [ 32.634578] k3s[825]: I0918 13:10:50.484584 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-tmp\") pod \"helm-install-niks3-7snlh\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") " pod="kube-system/helm-install-niks3-7snlh"1597machine # [ 32.638785] k3s[825]: I0918 13:10:50.484604 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"values\" (UniqueName: \"kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-values\") pod \"helm-install-niks3-7snlh\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") " pod="kube-system/helm-install-niks3-7snlh"1598machine # [ 32.679737] k3s[825]: I0918 13:10:50.567859 825 iptables.go:111] Setting up masking rules1599machine # [ 32.690902] k3s[825]: I0918 13:10:50.579041 825 iptables.go:212] Changing default FORWARD chain policy to ACCEPT1600machine # [ 32.714528] k3s[825]: time="2026-09-18T13:10:50Z" level=info msg="Wrote flannel subnet file to /run/flannel/subnet.env"1601machine # [ 32.717087] k3s[825]: time="2026-09-18T13:10:50Z" level=info msg="Running flannel backend"1602machine # [ 32.718298] k3s[825]: I0918 13:10:50.602674 825 vxlan_network.go:68] watching for new subnet leases1603machine # [ 32.719613] k3s[825]: I0918 13:10:50.602699 825 vxlan_network.go:115] starting vxlan device watcher1604machine # [ 32.787817] k3s[825]: I0918 13:10:50.675991 825 iptables.go:358] bootstrap done1605machine # [ 32.806547] k3s[825]: I0918 13:10:50.694726 825 iptables.go:358] bootstrap done1606machine # [ 32.980755] cni0: port 1(vethea7b943e) entered blocking state1607machine # [ 32.980796] cni0: port 1(vethea7b943e) entered disabled state1608machine # [ 32.980848] vethea7b943e: entered allmulticast mode1609machine # [ 32.980950] vethea7b943e: entered promiscuous mode1610machine # [ 32.980278] (udev-worker)[1079]: Network interface NamePolicy= disabled on kernel command line.1611machine # [ 32.990887] cni0: port 2(veth80376a04) entered blocking state1612machine # [ 32.990930] cni0: port 2(veth80376a04) entered disabled state1613machine # [ 32.990971] veth80376a04: entered allmulticast mode1614machine # [ 32.991077] veth80376a04: entered promiscuous mode1615machine # [ 32.999635] cni0: port 1(vethea7b943e) entered blocking state1616machine # [ 32.999672] cni0: port 1(vethea7b943e) entered forwarding state1617machine # [ 33.016571] cni0: port 2(veth80376a04) entered blocking state1618machine # [ 33.016606] cni0: port 2(veth80376a04) entered forwarding state1619machine # [ 33.042154] dhcpcd[612]: vethea7b943e: IAID 5c:59:07:d81620machine # [ 33.043143] dhcpcd[612]: vethea7b943e: adding address fe80::d42e:5cff:fe59:7d81621machine # [ 33.060096] dhcpcd[612]: veth80376a04: IAID 36:61:00:4e1622machine # [ 33.060910] dhcpcd[612]: veth80376a04: adding address fe80::4017:36ff:fe61:4e1623machine # [ 33.264717] systemd[1]: Started libcontainer container 8edbc0f3c3cabb54d7e2302f443455ea2625b8ad6209ddd7103169050eb9219b.1624machine # [ 33.271824] systemd[1]: Started libcontainer container 24a8a9d972ad91f72d7c05be19063d35854b5faf02026687b3ec77c5f660247d.1625machine # Error from server (NotFound): namespaces "niks3" not found1626machine # [ 33.759472] dhcpcd[612]: veth80376a04: soliciting a DHCP lease1627machine # [ 34.176866] dhcpcd[612]: flannel.1: soliciting a DHCP lease1628machine # Error from server (NotFound): namespaces "niks3" not found1629machine # [ 34.641366] dhcpcd[612]: veth80376a04: soliciting an IPv6 router1630machine # [ 34.842122] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount3722680282.mount: Deactivated successfully.1631machine # [ 34.893216] systemd[1]: Started libcontainer container db04f5c8eb41d1c4def332f827a229bc18226b20b3db95c24bf3dd976584d77f.1632machine # [ 34.906305] dhcpcd[612]: vethea7b943e: soliciting a DHCP lease1633machine # [ 34.929517] dhcpcd[612]: flannel.1: soliciting an IPv6 router1634machine # [ 35.060941] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount1163330579.mount: Deactivated successfully.1635machine # [ 35.104778] systemd[1]: Started libcontainer container e6ff29b4cca3477593b88c1676ec9db9d25d638bde0688b9e93c70dd8cbbc88c.1636machine # [ 35.260108] k3s[825]: I0918 13:10:53.144930 825 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/coredns-c5fdd76cf-n7qs8" podStartSLOduration=3.14490926 podStartE2EDuration="3.14490926s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-18 13:10:50 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-18 13:10:53.1218557 +0000 UTC m=+16.077302161" watchObservedRunningTime="2026-09-18 13:10:53.14490926 +0000 UTC m=+16.100355741"1637machine # [ 35.288630] k3s[825]: I0918 13:10:53.173798 825 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/helm-install-niks3-7snlh" podStartSLOduration=3.17377756 podStartE2EDuration="3.17377756s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-18 13:10:50 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-18 13:10:53.14531154 +0000 UTC m=+16.100758021" watchObservedRunningTime="2026-09-18 13:10:53.17377756 +0000 UTC m=+16.129224041"1638machine # [ 35.355922] dhcpcd[612]: vethea7b943e: soliciting an IPv6 router1639machine # [ 35.401165] k3s[825]: time="2026-09-18T13:10:53Z" level=info msg="Started tunnel to 10.0.2.15:6443"1640machine # [ 35.403165] k3s[825]: time="2026-09-18T13:10:53Z" level=info msg="Stopped tunnel to 127.0.0.1:6443"1641machine # [ 35.405041] k3s[825]: time="2026-09-18T13:10:53Z" level=info msg="Connecting to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1642machine # [ 35.407068] k3s[825]: time="2026-09-18T13:10:53Z" level=info msg="Proxy done" err="context canceled" url="wss://127.0.0.1:6443/v1-k3s/connect"1643machine # [ 35.409444] k3s[825]: time="2026-09-18T13:10:53Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF"1644machine # [ 35.411965] k3s[825]: time="2026-09-18T13:10:53Z" level=info msg="Handling backend connection request [machine]"1645machine # [ 35.413890] k3s[825]: time="2026-09-18T13:10:53Z" level=info msg="Connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1646machine # [ 35.415911] k3s[825]: time="2026-09-18T13:10:53Z" level=info msg="Remotedialer connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1647machine # Error from server (NotFound): namespaces "niks3" not found1648machine # [ 36.139681] k3s[825]: I0918 13:10:54.027823 825 alloc.go:329] "allocated clusterIPs" service="niks3/niks3" clusterIPs={"IPv4":"10.43.193.123"}1649machine # [ 36.159405] k3s[825]: I0918 13:10:54.047393 825 controller.go:667] quota admission added evaluator for: cronjobs.batch1650machine # [ 36.184911] systemd[1]: cri-containerd-e6ff29b4cca3477593b88c1676ec9db9d25d638bde0688b9e93c70dd8cbbc88c.scope: Deactivated successfully.1651machine # [ 36.188619] systemd[1]: cri-containerd-e6ff29b4cca3477593b88c1676ec9db9d25d638bde0688b9e93c70dd8cbbc88c.scope: Consumed 849ms CPU time over 1.080s wall clock time, 32.4M memory peak, 4.1M incoming IP traffic, 80.6K outgoing IP traffic.1652machine # [ 36.226220] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-e6ff29b4cca3477593b88c1676ec9db9d25d638bde0688b9e93c70dd8cbbc88c-rootfs.mount: Deactivated successfully.1653machine # [ 36.336205] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod6d0d4d17_3590_4ff7_aafd_a0ab87e12ea1.slice.1654machine # [ 36.430851] k3s[825]: I0918 13:10:54.318242 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"db\" (UniqueName: \"kubernetes.io/secret/6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1-db\") pod \"niks3-5c78d87487-dqwcx\" (UID: \"6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1\") " pod="niks3/niks3-5c78d87487-dqwcx"1655machine # [ 36.438190] k3s[825]: I0918 13:10:54.318304 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"oidc\" (UniqueName: \"kubernetes.io/configmap/6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1-oidc\") pod \"niks3-5c78d87487-dqwcx\" (UID: \"6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1\") " pod="niks3/niks3-5c78d87487-dqwcx"1656machine # [ 36.445287] k3s[825]: I0918 13:10:54.318336 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1-token\") pod \"niks3-5c78d87487-dqwcx\" (UID: \"6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1\") " pod="niks3/niks3-5c78d87487-dqwcx"1657machine # [ 36.451677] k3s[825]: I0918 13:10:54.318414 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"s3\" (UniqueName: \"kubernetes.io/secret/6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1-s3\") pod \"niks3-5c78d87487-dqwcx\" (UID: \"6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1\") " pod="niks3/niks3-5c78d87487-dqwcx"1658machine # [ 36.457669] k3s[825]: I0918 13:10:54.318443 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-bz77v\" (UniqueName: \"kubernetes.io/projected/6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1-kube-api-access-bz77v\") pod \"niks3-5c78d87487-dqwcx\" (UID: \"6d0d4d17-3590-4ff7-aafd-a0ab87e12ea1\") " pod="niks3/niks3-5c78d87487-dqwcx"1659machine # [ 36.712081] cni0: port 3(veth97be5674) entered blocking state1660machine # [ 36.712161] cni0: port 3(veth97be5674) entered disabled state1661machine # [ 36.712261] veth97be5674: entered allmulticast mode1662machine # [ 36.712466] veth97be5674: entered promiscuous mode1663machine # [ 36.735025] cni0: port 3(veth97be5674) entered blocking state1664machine # [ 36.735094] cni0: port 3(veth97be5674) entered forwarding state1665machine # [ 36.828970] (udev-worker)[1606]: Network interface NamePolicy= disabled on kernel command line.1666machine # [ 36.898016] dhcpcd[612]: veth97be5674: IAID 7a:13:77:251667machine # [ 36.899026] dhcpcd[612]: veth97be5674: adding address fe80::3483:7aff:fe13:77251668machine # [ 36.924395] systemd[1]: Started libcontainer container 0899515b0e11734f12d3b8bb288fa9a04d59767c55941c66529be2968a7c33a6.1669machine # [ 37.429012] systemd[1]: Started libcontainer container 562aa7c8e2d16fe37a012fb3169b63160970c974ddbdb1c6dc15c90f62094812.1670machine # [ 37.542985] postgres[1696]: [1696] ERROR: relation "goose_db_version" does not exist at character 361671machine # [ 37.544773] postgres[1696]: [1696] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1672machine # [ 38.266390] systemd[1]: cri-containerd-24a8a9d972ad91f72d7c05be19063d35854b5faf02026687b3ec77c5f660247d.scope: Deactivated successfully.1673machine # [ 38.341614] dhcpcd[612]: veth97be5674: soliciting a DHCP lease1674machine # [ 38.356108] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-24a8a9d972ad91f72d7c05be19063d35854b5faf02026687b3ec77c5f660247d-rootfs.mount: Deactivated successfully.1675machine # [ 38.493081] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-24a8a9d972ad91f72d7c05be19063d35854b5faf02026687b3ec77c5f660247d-shm.mount: Deactivated successfully.1676machine # [ 38.549066] cni0: port 1(vethea7b943e) entered disabled state1677machine # [ 38.551339] vethea7b943e (unregistering): left allmulticast mode1678machine # [ 38.548697] dhcpcd[612]: vethea7b943e: carrier lost[ 38.551391] vethea7b943e (unregistering): left promiscuous mode1679machine # [ 38.551412] cni0: port 1(vethea7b943e) entered disabled state1680machine # 1681machine # [ 38.565521] k3s[825]: I0918 13:10:56.453186 825 kuberuntime_manager.go:2095] "Updating runtime config through cri with podcidr" CIDR="10.42.0.0/24"1682machine # [ 38.572104] k3s[825]: I0918 13:10:56.454326 825 kubelet_network.go:47] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="10.42.0.0/24"1683machine # [ 38.593248] systemd[1]: run-netns-cni\x2d313f8d89\x2d79f5\x2d5e52\x2dcf34\x2d71aff5e26010.mount: Deactivated successfully.1684machine # [ 38.614309] dhcpcd[612]: vethea7b943e: deleting address fe80::d42e:5cff:fe59:7d81685machine # [ 38.636379] k3s[825]: I0918 13:10:56.524522 825 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/niks3-5c78d87487-dqwcx" podStartSLOduration=2.52449324 podStartE2EDuration="2.52449324s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-18 13:10:54 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-18 13:10:56.15531378 +0000 UTC m=+19.110760281" watchObservedRunningTime="2026-09-18 13:10:56.52449324 +0000 UTC m=+19.479939721"1686machine # [ 38.668495] dhcpcd[612]: vethea7b943e: removing interface1687machine # [ 38.759531] dhcpcd[612]: veth80376a04: probing for an IPv4LL address1688machine # [ 38.765148] k3s[825]: I0918 13:10:56.652091 825 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-config\") pod \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") "1689machine # [ 38.786466] k3s[825]: I0918 13:10:56.652221 825 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-tmp\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-tmp\") pod \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") "1690machine # [ 38.799943] k3s[825]: I0918 13:10:56.652278 825 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-values\" (UniqueName: \"kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-values\") pod \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") "1691machine # [ 38.813039] k3s[825]: I0918 13:10:56.652387 825 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/configmap/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-content\" (UniqueName: \"kubernetes.io/configmap/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-content\") pod \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") "1692machine # [ 38.822340] k3s[825]: I0918 13:10:56.652440 825 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-kube-api-access-6fw8r\" (UniqueName: \"kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-kube-api-access-6fw8r\") pod \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") "1693machine # [ 38.830548] k3s[825]: I0918 13:10:56.652508 825 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-helm\") pod \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") "1694machine # [ 38.837697] k3s[825]: I0918 13:10:56.652560 825 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-cache\") pod \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\" (UID: \"a4777e0f-1e25-4426-81e9-c06bf6ccaeed\") "1695machine # [ 38.844405] k3s[825]: I0918 13:10:56.678393 825 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/configmap/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-content" pod "a4777e0f-1e25-4426-81e9-c06bf6ccaeed" (UID: "a4777e0f-1e25-4426-81e9-c06bf6ccaeed"). InnerVolumeSpecName "content". PluginName "kubernetes.io/configmap", VolumeGIDValue ""1696machine # [ 38.851241] k3s[825]: I0918 13:10:56.692373 825 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-config" pod "a4777e0f-1e25-4426-81e9-c06bf6ccaeed" (UID: "a4777e0f-1e25-4426-81e9-c06bf6ccaeed"). InnerVolumeSpecName "klipper-config". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1697machine # [ 38.857477] k3s[825]: I0918 13:10:56.703032 825 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-kube-api-access-6fw8r" pod "a4777e0f-1e25-4426-81e9-c06bf6ccaeed" (UID: "a4777e0f-1e25-4426-81e9-c06bf6ccaeed"). InnerVolumeSpecName "kube-api-access-6fw8r". PluginName "kubernetes.io/projected", VolumeGIDValue ""1698machine # [ 38.863789] k3s[825]: I0918 13:10:56.703503 825 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-tmp" pod "a4777e0f-1e25-4426-81e9-c06bf6ccaeed" (UID: "a4777e0f-1e25-4426-81e9-c06bf6ccaeed"). InnerVolumeSpecName "tmp". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1699machine # [ 38.869792] k3s[825]: I0918 13:10:56.703578 825 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-cache" pod "a4777e0f-1e25-4426-81e9-c06bf6ccaeed" (UID: "a4777e0f-1e25-4426-81e9-c06bf6ccaeed"). InnerVolumeSpecName "klipper-cache". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1700machine # [ 38.875879] k3s[825]: I0918 13:10:56.712157 825 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-values" pod "a4777e0f-1e25-4426-81e9-c06bf6ccaeed" (UID: "a4777e0f-1e25-4426-81e9-c06bf6ccaeed"). InnerVolumeSpecName "values". PluginName "kubernetes.io/projected", VolumeGIDValue ""1701machine # [ 38.881773] k3s[825]: I0918 13:10:56.712395 825 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-helm" pod "a4777e0f-1e25-4426-81e9-c06bf6ccaeed" (UID: "a4777e0f-1e25-4426-81e9-c06bf6ccaeed"). InnerVolumeSpecName "klipper-helm". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1702machine # [ 38.887409] systemd[1]: var-lib-kubelet-pods-a4777e0f\x2d1e25\x2d4426\x2d81e9\x2dc06bf6ccaeed-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dconfig.mount: Deactivated successfully.1703machine # [ 38.890170] dhcpcd[612]: veth97be5674: soliciting an IPv6 router1704machine # [ 38.891229] k3s[825]: I0918 13:10:56.753316 825 reconciler_common.go:299] "Volume detached for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-config\") on node \"machine\" DevicePath \"\""1705machine # [ 38.894805] k3s[825]: I0918 13:10:56.753376 825 reconciler_common.go:299] "Volume detached for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-tmp\") on node \"machine\" DevicePath \"\""1706machine # [ 38.897931] k3s[825]: I0918 13:10:56.753403 825 reconciler_common.go:299] "Volume detached for volume \"values\" (UniqueName: \"kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-values\") on node \"machine\" DevicePath \"\""1707machine # [ 38.901066] k3s[825]: I0918 13:10:56.753429 825 reconciler_common.go:299] "Volume detached for volume \"content\" (UniqueName: \"kubernetes.io/configmap/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-content\") on node \"machine\" DevicePath \"\""1708machine # [ 38.904157] k3s[825]: I0918 13:10:56.753456 825 reconciler_common.go:299] "Volume detached for volume \"kube-api-access-6fw8r\" (UniqueName: \"kubernetes.io/projected/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-kube-api-access-6fw8r\") on node \"machine\" DevicePath \"\""1709machine # [ 38.907470] k3s[825]: I0918 13:10:56.753483 825 reconciler_common.go:299] "Volume detached for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-helm\") on node \"machine\" DevicePath \"\""1710machine # [ 38.910688] k3s[825]: I0918 13:10:56.753512 825 reconciler_common.go:299] "Volume detached for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/a4777e0f-1e25-4426-81e9-c06bf6ccaeed-klipper-cache\") on node \"machine\" DevicePath \"\""1711machine # [ 38.913811] systemd[1]: var-lib-kubelet-pods-a4777e0f\x2d1e25\x2d4426\x2d81e9\x2dc06bf6ccaeed-volumes-kubernetes.io\x7eprojected-kube\x2dapi\x2daccess\x2d6fw8r.mount: Deactivated successfully.1712machine # [ 38.916108] systemd[1]: var-lib-kubelet-pods-a4777e0f\x2d1e25\x2d4426\x2d81e9\x2dc06bf6ccaeed-volumes-kubernetes.io\x7eempty\x2ddir-tmp.mount: Deactivated successfully.1713machine # [ 38.918027] systemd[1]: var-lib-kubelet-pods-a4777e0f\x2d1e25\x2d4426\x2d81e9\x2dc06bf6ccaeed-volumes-kubernetes.io\x7eprojected-values.mount: Deactivated successfully.1714machine # [ 38.919924] systemd[1]: var-lib-kubelet-pods-a4777e0f\x2d1e25\x2d4426\x2d81e9\x2dc06bf6ccaeed-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dhelm.mount: Deactivated successfully.1715machine # [ 38.922122] systemd[1]: var-lib-kubelet-pods-a4777e0f\x2d1e25\x2d4426\x2d81e9\x2dc06bf6ccaeed-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dcache.mount: Deactivated successfully.1716machine # [ 39.178307] dhcpcd[612]: flannel.1: probing for an IPv4LL address1717machine # [ 39.248144] k3s[825]: I0918 13:10:57.132391 825 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="24a8a9d972ad91f72d7c05be19063d35854b5faf02026687b3ec77c5f660247d"1718machine # [ 39.267739] systemd[1]: Removed slice libcontainer container kubepods-burstable-poda4777e0f_1e25_4426_81e9_c06bf6ccaeed.slice.1719machine # [ 39.280413] systemd[1]: kubepods-burstable-poda4777e0f_1e25_4426_81e9_c06bf6ccaeed.slice: Consumed 878ms CPU time over 6.732s wall clock time, 32.6M memory peak, 4.1M incoming IP traffic, 80.6K outgoing IP traffic.1720machine # [ 39.581709] k3s[825]: time="2026-09-18T13:10:57Z" level=info msg="Starting network policy controller version v2.6.3-k3s1, built on 1970-01-01T01:01:01Z, go1.26.7"1721machine # [ 39.588196] k3s[825]: I0918 13:10:57.468740 825 network_policy_controller.go:164] Starting network policy controller1722machine # [ 39.844754] k3s[825]: I0918 13:10:57.732877 825 network_policy_controller.go:179] Starting network policy controller full sync goroutine1723machine # [ 43.345582] dhcpcd[612]: veth97be5674: probing for an IPv4LL address1724machine # [ 43.918008] dhcpcd[612]: flannel.1: using IPv4LL address 169.254.145.101725machine # [ 43.922923] dhcpcd[612]: flannel.1: adding route to 169.254.0.0/161726machine # [ 44.070079] dhcpcd[612]: veth80376a04: using IPv4LL address 169.254.93.71727machine # [ 44.073511] dhcpcd[612]: veth80376a04: adding route to 169.254.0.0/161728machine # [ 45.902613] k3s[825]: I0918 13:11:03.787942 825 prober_manager.go:356] "Failed to trigger a manual run" probe="Readiness"1729machine: (finished: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s, in 19.88 seconds)1730machine: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true1731machine: (finished: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true, in 0.41 seconds)1732machine: waiting for success: curl -sf http://localhost:30051/readyz | grep OK1733machine: (finished: waiting for success: curl -sf http://localhost:30051/readyz | grep OK, in 0.08 seconds)1734(finished: subtest: chart deploys and becomes ready, in 20.36 seconds)1735machine: waiting for success: kubectl -n ci get sa builder1736machine # [ 46.674026] dhcpcd[612]: veth80376a04: no IPv6 Routers available1737machine # [ 46.932500] dhcpcd[612]: flannel.1: no IPv6 Routers available1738machine: (finished: waiting for success: kubectl -n ci get sa builder, in 0.44 seconds)1739machine: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt1740machine: (finished: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt, in 0.23 seconds)1741machine: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt1742machine # [ 47.374554] dhcpcd[612]: veth97be5674: using IPv4LL address 169.254.47.1301743machine # [ 47.379312] dhcpcd[612]: veth97be5674: adding route to 169.254.0.0/161744machine: (finished: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt, in 0.18 seconds)1745machine: must succeed: readlink -f /run/current-system/sw/bin/niks31746machine: (finished: must succeed: readlink -f /run/current-system/sw/bin/niks3, in 0.02 seconds)1747subtest: allowed service account can push via workload identity1748machine: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/h6i978bb9bhfi5sbs5i9y24xjmndr95k-niks3-1.11.0 2>&11749machine: (finished: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/h6i978bb9bhfi5sbs5i9y24xjmndr95k-niks3-1.11.0 2>&1, in 1.12 seconds)1750machine: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/h6i978bb9bhfi5sbs5i9y24xjmndr95k.narinfo1751machine: (finished: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/h6i978bb9bhfi5sbs5i9y24xjmndr95k.narinfo, in 0.03 seconds)1752(finished: subtest: allowed service account can push via workload identity, in 1.15 seconds)1753subtest: write scope does not grant admin1754machine: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status1755machine: (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.04 seconds)1756(finished: subtest: write scope does not grant admin, in 0.04 seconds)1757subtest: other service accounts are rejected1758machine: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/h6i978bb9bhfi5sbs5i9y24xjmndr95k-niks3-1.11.0 2>&11759machine: (finished: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/h6i978bb9bhfi5sbs5i9y24xjmndr95k-niks3-1.11.0 2>&1, in 0.14 seconds)1760(finished: subtest: other service accounts are rejected, in 0.14 seconds)1761subtest: gc cronjob runs against the service1762machine: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual1763machine: (finished: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual, in 0.19 seconds)1764machine: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s1765machine # [ 49.084861] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod72d1584c_509d_4836_bcf6_22304aa19db2.slice.1766machine # [ 49.086993] k3s[825]: I0918 13:11:06.971713 825 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/72d1584c-509d-4836-bcf6-22304aa19db2-token\") pod \"gc-manual-plz2s\" (UID: \"72d1584c-509d-4836-bcf6-22304aa19db2\") " pod="niks3/gc-manual-plz2s"1767machine # [ 49.474051] cni0: port 1(vethcc483eb2) entered blocking state1768machine # [ 49.474088] cni0: port 1(vethcc483eb2) entered disabled state1769machine # [ 49.474139] vethcc483eb2: entered allmulticast mode1770machine # [ 49.474245] vethcc483eb2: entered promiscuous mode1771machine # [ 49.491189] cni0: port 1(vethcc483eb2) entered blocking state1772machine # [ 49.491223] cni0: port 1(vethcc483eb2) entered forwarding state1773machine # [ 49.526921] (udev-worker)[2128]: Network interface NamePolicy= disabled on kernel command line.1774machine # [ 49.561883] dhcpcd[612]: vethcc483eb2: IAID da:03:1e:6f1775machine # [ 49.562754] dhcpcd[612]: vethcc483eb2: adding address fe80::f809:daff:fe03:1e6f1776machine # [ 49.608504] systemd[1]: Started libcontainer container 5cec85dcdf984983f149048619aa7589682df6d2b9a5c2a25f0e48ac7650486a.1777machine # [ 49.724475] systemd[1]: Started libcontainer container c5f83fc42ff1a6173eea2ad6b52df80aca050614e54ba7dbe02245775bdc6dd7.1778machine # [ 50.348262] k3s[825]: I0918 13:11:08.235140 825 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/gc-manual-plz2s" podStartSLOduration=2.23506862 podStartE2EDuration="2.23506862s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-18 13:11:06 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-18 13:11:08.23138464 +0000 UTC m=+31.186831181" watchObservedRunningTime="2026-09-18 13:11:08.23506862 +0000 UTC m=+31.190515141"1779machine # [ 50.873951] dhcpcd[612]: veth97be5674: no IPv6 Routers available1780machine # [ 51.310123] dhcpcd[612]: vethcc483eb2: soliciting a DHCP lease1781machine # [ 51.627475] dhcpcd[612]: vethcc483eb2: soliciting an IPv6 router1782machine # [ 51.795737] systemd[1]: cri-containerd-c5f83fc42ff1a6173eea2ad6b52df80aca050614e54ba7dbe02245775bdc6dd7.scope: Deactivated successfully.1783machine # [ 51.802170] systemd[1]: cri-containerd-c5f83fc42ff1a6173eea2ad6b52df80aca050614e54ba7dbe02245775bdc6dd7.scope: Consumed 36ms CPU time over 2.070s wall clock time, 3.8M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic.1784machine # [ 51.891058] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-c5f83fc42ff1a6173eea2ad6b52df80aca050614e54ba7dbe02245775bdc6dd7-rootfs.mount: Deactivated successfully.1785machine # [ 53.382646] systemd[1]: cri-containerd-5cec85dcdf984983f149048619aa7589682df6d2b9a5c2a25f0e48ac7650486a.scope: Deactivated successfully.1786machine # [ 53.469589] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-5cec85dcdf984983f149048619aa7589682df6d2b9a5c2a25f0e48ac7650486a-rootfs.mount: Deactivated successfully.1787machine # [ 53.517150] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-5cec85dcdf984983f149048619aa7589682df6d2b9a5c2a25f0e48ac7650486a-shm.mount: Deactivated successfully.1788machine # [ 53.576290] cni0: port 1(vethcc483eb2) entered disabled state1789machine # [ 53.575840] dhcpcd[612]: vethcc483eb2: carrier lost[ 53.579492] vethcc483eb2 (unregistering): left allmulticast mode1790machine # [ 53.579599] vethcc483eb2 (unregistering): left promiscuous mode1791machine # 1792machine # [ 53.579630] cni0: port 1(vethcc483eb2) entered disabled state1793machine # [ 53.622248] systemd[1]: run-netns-cni\x2d7cf71812\x2d56f1\x2db67e\x2d729f\x2d3b6da1f9083f.mount: Deactivated successfully.1794machine # [ 53.639330] dhcpcd[612]: vethcc483eb2: deleting address fe80::f809:daff:fe03:1e6f1795machine # [ 53.696310] dhcpcd[612]: vethcc483eb2: removing interface1796machine # [ 53.731102] k3s[825]: I0918 13:11:11.618914 825 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/secret/72d1584c-509d-4836-bcf6-22304aa19db2-token\" (UniqueName: \"kubernetes.io/secret/72d1584c-509d-4836-bcf6-22304aa19db2-token\") pod \"72d1584c-509d-4836-bcf6-22304aa19db2\" (UID: \"72d1584c-509d-4836-bcf6-22304aa19db2\") "1797machine # [ 53.739358] systemd[1]: var-lib-kubelet-pods-72d1584c\x2d509d\x2d4836\x2dbcf6\x2d22304aa19db2-volumes-kubernetes.io\x7esecret-token.mount: Deactivated successfully.1798machine # [ 53.742204] k3s[825]: I0918 13:11:11.630415 825 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/72d1584c-509d-4836-bcf6-22304aa19db2-token" pod "72d1584c-509d-4836-bcf6-22304aa19db2" (UID: "72d1584c-509d-4836-bcf6-22304aa19db2"). InnerVolumeSpecName "token". PluginName "kubernetes.io/secret", VolumeGIDValue ""1799machine # [ 53.830918] k3s[825]: I0918 13:11:11.719110 825 reconciler_common.go:299] "Volume detached for volume \"token\" (UniqueName: \"kubernetes.io/secret/72d1584c-509d-4836-bcf6-22304aa19db2-token\") on node \"machine\" DevicePath \"\""1800machine # [ 54.018870] systemd[1]: Removed slice libcontainer container kubepods-besteffort-pod72d1584c_509d_4836_bcf6_22304aa19db2.slice.1801machine # [ 54.024745] systemd[1]: kubepods-besteffort-pod72d1584c_509d_4836_bcf6_22304aa19db2.slice: Consumed 61ms CPU time over 4.935s wall clock time, 4.5M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic.1802machine # [ 54.352183] k3s[825]: I0918 13:11:12.240096 825 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="5cec85dcdf984983f149048619aa7589682df6d2b9a5c2a25f0e48ac7650486a"1803machine: (finished: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s, in 5.41 seconds)1804(finished: subtest: gc cronjob runs against the service, in 5.60 seconds)1805subtest: helm test hook passes1806machine: must succeed: helm test -n niks3 niks3 --timeout 2m >&21807machine # [ 55.640111] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod4c252bcc_2262_4e68_b029_4fd69e68b9aa.slice.1808machine # [ 55.701478] cni0: port 1(veth188763f0) entered blocking state1809machine # [ 55.701521] cni0: port 1(veth188763f0) entered disabled state1810machine # [ 55.701559] veth188763f0: entered allmulticast mode1811machine # [ 55.701672] veth188763f0: entered promiscuous mode1812machine # [ 55.704991] (udev-worker)[2339]: Network interface NamePolicy= disabled on kernel command line.1813machine # [ 55.718890] cni0: port 1(veth188763f0) entered blocking state1814machine # [ 55.718933] cni0: port 1(veth188763f0) entered forwarding state1815machine # [ 55.761038] dhcpcd[612]: veth188763f0: IAID 89:6e:6a:061816machine # [ 55.762239] dhcpcd[612]: veth188763f0: adding address fe80::f85e:89ff:fe6e:6a061817machine # [ 55.852622] systemd[1]: Started libcontainer container 2aae47b6b909348866a239a852e118f73d728488ff1ae9ceb6f75dab4f645683.1818machine # [ 55.980688] systemd[1]: Started libcontainer container e0dc26aeb6c5f677c06371736b5c6f1fb0089a1fc3927a4fb4c75dfea5773a13.1819machine # [ 56.037524] systemd[1]: cri-containerd-e0dc26aeb6c5f677c06371736b5c6f1fb0089a1fc3927a4fb4c75dfea5773a13.scope: Deactivated successfully.1820machine # [ 56.039255] systemd[1]: cri-containerd-e0dc26aeb6c5f677c06371736b5c6f1fb0089a1fc3927a4fb4c75dfea5773a13.scope: Consumed 25ms CPU time over 56ms wall clock time, 4.1M memory peak, 693B incoming IP traffic, 547B outgoing IP traffic.1821machine # [ 56.240237] dhcpcd[612]: veth188763f0: soliciting a DHCP lease1822machine # [ 57.403781] systemd[1]: cri-containerd-2aae47b6b909348866a239a852e118f73d728488ff1ae9ceb6f75dab4f645683.scope: Deactivated successfully.1823machine # [ 57.489623] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-2aae47b6b909348866a239a852e118f73d728488ff1ae9ceb6f75dab4f645683-rootfs.mount: Deactivated successfully.1824machine # [ 57.543449] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-2aae47b6b909348866a239a852e118f73d728488ff1ae9ceb6f75dab4f645683-shm.mount: Deactivated successfully.1825machine # [ 57.604899] cni0: port 1(veth188763f0) entered disabled state1826machine # [ 57.605034] dhcpcd[612]: veth188763f0: carrier lost[ 57.608678] veth188763f0 (unregistering): left allmulticast mode1827machine # 1828machine # [ 57.608724] veth188763f0 (unregistering): left promiscuous mode1829machine # [ 57.608749] cni0: port 1(veth188763f0) entered disabled state1830machine # [ 57.643246] systemd[1]: run-netns-cni\x2d78358551\x2da854\x2d775b\x2da584\x2d0a170e818597.mount: Deactivated successfully.1831machine # [ 57.679134] dhcpcd[612]: veth188763f0: deleting address fe80::f85e:89ff:fe6e:6a061832machine # NAME: niks31833machine # LAST DEPLOYED: Fri Sep 18 13:10:53 20261834machine # NAMESPACE: niks31835machine # STATUS: deployed1836machine # REVISION: 11837machine # DESCRIPTION: Install complete1838machine # TEST SUITE: niks3-test1839machine # Last Started: Fri Sep 18 13:11:13 20261840machine # Last Completed: Fri Sep 18 13:11:15 20261841machine # Phase: Succeeded1842machine: (finished: must succeed: helm test -n niks3 niks3 --timeout 2m >&2, in 3.29 seconds)1843(finished: subtest: helm test hook passes, in 3.29 seconds)1844(finished: run the VM test script, in 58.83 seconds)1845machine # [ 57.768823] dhcpcd[612]: veth188763f0: removing interface1846test script finished in 58.88s1847cleanup1848kill QemuMachine (pid 45)1849machine # qemu-system-aarch64: terminating on signal 15 from pid 39 (/nix/store/3fl7bdkdxk2k4nssy1d1161isbzn6bsr-python3-3.14.7/bin/python3.14)1850machine # [2026-09-18T13:11:15Z INFO virtiofsd] Client disconnected, shutting down1851machine # [2026-09-18T13:11:15Z INFO virtiofsd] Client disconnected, shutting down1852machine # [2026-09-18T13:11:15Z INFO virtiofsd] Client disconnected, shutting down1853(finished: cleanup, in 0.87 seconds)1854additionally exposed symbols:1855 machine,1856 vlan1,1857 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_ssh1858time=2026-09-18T13:11:05.594Z level=INFO msg="Uploading 8 paths to localhost (0 already cached)"1859time=2026-09-18T13:11:05.594Z level=INFO msg="Uploading waax852balprvsvdziyaf1h7r3ldvakg-xgcc-15.3.0-libgcc (150.1KB)"1860time=2026-09-18T13:11:05.594Z level=INFO msg="Uploading n7aaryickpnkwwmmkg7xgnlihmmsh55w-mailcap-2.1.54 (116.6KB)"1861time=2026-09-18T13:11:05.594Z level=INFO msg="Uploading m54cs0m994hc3n9lax7sg98sgy729qsa-glibc-2.42-84 (44.4MB)"1862time=2026-09-18T13:11:05.595Z level=INFO msg="Uploading na3qajp3ja0w9yxcsqck86phm9ddhwx2-iana-etc-20251215 (557.8KB)"1863time=2026-09-18T13:11:05.597Z level=INFO msg="Uploading 0s40b0an0cz4vypbji92cb7qbr65icl4-libidn2-2.3.8 (366.1KB)"1864time=2026-09-18T13:11:05.598Z level=INFO msg="Uploading h6i978bb9bhfi5sbs5i9y24xjmndr95k-niks3-1.11.0 (7.1MB)"1865time=2026-09-18T13:11:05.599Z level=INFO msg="Uploading h0hd048jzxs7fx9a6g75jwrrhbg50bp8-libunistring-1.4.2 (2.0MB)"1866time=2026-09-18T13:11:05.599Z level=INFO msg="Uploading i8an849ir6g3f4n2wrsm88s2qgrzjayq-tzdata-2026c (2.0MB)"1867time=2026-09-18T13:11:06.477Z level=INFO msg="Uploading 8 narinfos"1868time=2026-09-18T13:11:06.518Z level=INFO msg="Upload complete. (1.02s)"1869