vm-test-run-nixos-test-k3s
checks.aarch64-linux.nixos-test-k3s
· build #317
· 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.JI5cORlrfQ', 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: cedf17f9-9466-4f86-bae6-b91000bdaa1317machine # Superblock backups stored on blocks:18machine # 32768, 98304, 163840, 229376, 294912, 819200, 884736, 160563219machine # 20machine # Allocating group tables: 0/64 done21machine # Writing inode tables: 0/64 done22machine # Creating journal (16384 blocks): done23machine # Writing superblocks and filesystem accounting information: 0/64 done24machine # 25machine # Virtualisation disk image created.26machine # Starting virtiofs daemons...27machine # [2026-10-01T09:46:29Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)28machine # [2026-10-01T09:46:29Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether29machine # [2026-10-01T09:46:29Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)30machine # [2026-10-01T09:46:29Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether31machine # [2026-10-01T09:46:29Z WARN virtiofsd::passthrough] Failed to open file handle for the root node: Operation not permitted (os error 1)32machine # [2026-10-01T09:46:29Z WARN virtiofsd::passthrough] File handles do not appear safe to use, disabling file handles altogether33machine # [2026-10-01T09:46:29Z INFO virtiofsd] Waiting for vhost-user socket connection...34machine # [2026-10-01T09:46:29Z INFO virtiofsd] Waiting for vhost-user socket connection...35machine # [2026-10-01T09:46:29Z INFO virtiofsd] Waiting for vhost-user socket connection...36machine # [2026-10-01T09:46:29Z INFO virtiofsd] Client connected, servicing requests37machine # [2026-10-01T09:46:29Z INFO virtiofsd] Client connected, servicing requests38machine # [2026-10-01T09:46:29Z INFO virtiofsd] Client connected, servicing requests39machine # [ 0.000000] Booting Linux on physical CPU 0x0000000000 [0xc00fac40]40machine # [ 0.000000] Linux version 6.18.54 (nixbld@localhost) (gcc (GCC) 15.3.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT Fri Sep 25 14:35:54 UTC 202641machine # [ 0.000000] KASLR enabled42machine # [ 0.000000] random: crng init done43machine # [ 0.000000] Machine model: linux,dummy-virt44machine # [ 0.000000] efi: UEFI not found.45machine # [ 0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT46machine # [ 0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000ffffffff]47machine # [ 0.000000] NODE_DATA(0) allocated [mem 0xffded0c0-0xffdf083f]48machine # [ 0.000000] Zone ranges:49machine # [ 0.000000] DMA [mem 0x0000000040000000-0x00000000ffffffff]50machine # [ 0.000000] DMA32 empty51machine # [ 0.000000] Normal empty52machine # [ 0.000000] Device empty53machine # [ 0.000000] Movable zone start for each node54machine # [ 0.000000] Early memory node ranges55machine # [ 0.000000] node 0: [mem 0x0000000040000000-0x00000000ffffffff]56machine # [ 0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000ffffffff]57machine # [ 0.000000] cma: Reserved 32 MiB at 0x00000000fac0000058machine # [ 0.000000] psci: probing for conduit method from DT.59machine # [ 0.000000] psci: PSCIv1.3 detected in firmware.60machine # [ 0.000000] psci: Using standard PSCI v0.2 function IDs61machine # [ 0.000000] psci: Trusted OS migration not required62machine # [ 0.000000] psci: SMC Calling Convention v1.163machine # [ 0.000000] smccc: KVM: hypervisor services detected (0x00000000 0x00000000 0x00000000 0x00000003)64machine # [ 0.000000] percpu: Embedded 76 pages/cpu s186776 r8192 d116328 u31129665machine # [ 0.000000] Detected PIPT I-cache on CPU066machine # [ 0.000000] CPU features: detected: Address authentication (architected QARMA5 algorithm)67machine # [ 0.000000] CPU features: detected: GICv3 CPU interface68machine # [ 0.000000] CPU features: detected: Spectre-v469machine # [ 0.000000] CPU features: detected: Spectre-BHB70machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC03_CPU_3871machine # [ 0.000000] CPU features: detected: AmpereOne erratum AC04_CPU_2372machine # [ 0.000000] alternatives: applying boot alternatives73machine # [ 0.000000] Kernel command line: console=ttyAMA0 console=tty0 panic=1 boot.panic_on_fail clocksource=acpi_pm root=fstab loglevel=7 net.ifnames=0 lsm=landlock,yama,bpf init=/nix/store/j73pylzh16dmx4531s4ra64gv96654f6-nixos-system-machine-test/init regInfo=/nix/.ro-store/7izvsfkwyn0bi9kk10a0z1rrjqrs31l2-closure-info/registration console=ttyAMA0,115200n8 console=tty074machine # [ 0.000000] Unknown kernel command line parameters "regInfo=/nix/.ro-store/7izvsfkwyn0bi9kk10a0z1rrjqrs31l2-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 74966 entries in 294 pages89machine # [ 0.000000] ftrace: allocated 294 pages with 4 groups90machine # [ 0.000000] rcu: Hierarchical RCU implementation.91machine # [ 0.000000] rcu: RCU event tracing is enabled.92machine # [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=2.93machine # [ 0.000000] Trampoline variant of Tasks RCU enabled.94machine # [ 0.000000] Rude variant of Tasks RCU enabled.95machine # [ 0.000000] Tracing variant of Tasks RCU enabled.96machine # [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.97machine # [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=298machine # [ 0.000000] RCU Tasks: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.99machine # [ 0.000000] RCU Tasks Rude: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.100machine # [ 0.000000] RCU Tasks Trace: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.101machine # [ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0102machine # [ 0.000000] GICv3: 256 SPIs implemented103machine # [ 0.000000] GICv3: 0 Extended SPIs implemented104machine # [ 0.000000] Root IRQ handler: gic_handle_irq105machine # [ 0.000000] GICv3: GICv3 features: 16 PPIs, DirectLPI106machine # [ 0.000000] GICv3: GICD_CTLR.DS=1, SCR_EL3.FIQ=0107machine # [ 0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a0000108machine # [ 0.000000] ITS [mem 0x08080000-0x0809ffff]109machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Devices @45100000 (indirect, esz 8, psz 64K, shr 1)110machine # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @45110000 (flat, esz 8, psz 64K, shr 1)111machine # [ 0.000000] GICv3: using LPI property table @0x0000000045130000112machine # [ 0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000045140000113machine # [ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.114machine # [ 0.000000] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns115machine # [ 0.000000] arch_timer: cp15 timer running at 1000.00MHz (virt).116machine # [ 0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns117machine # [ 0.000000] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns118machine # [ 0.000031] arm-pv: using stolen time PV119machine # [ 0.000402] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)120machine # [ 0.000617] Console: colour dummy device 80x25121machine # [ 0.000624] printk: legacy console [tty0] enabled122machine # [ 0.000817] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000)123machine # [ 0.000824] pid_max: default: 32768 minimum: 301124machine # [ 0.000907] LSM: initializing lsm=capability,landlock,yama,bpf,ima125machine # [ 0.001043] landlock: Up and running.126machine # [ 0.001046] Yama: becoming mindful.127machine # [ 0.001492] LSM support for eBPF active128machine # [ 0.001674] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)129machine # [ 0.001739] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)130machine # [ 0.003970] rcu: Hierarchical SRCU implementation.131machine # [ 0.003976] rcu: Max phase no-delay instances is 1000.132machine # [ 0.004179] Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level133machine # [ 0.005421] fsl-mc MSI: its@8080000 domain created134machine # [ 0.005551] EFI services will not be available.135machine # [ 0.005671] smp: Bringing up secondary CPUs ...136machine # [ 0.006234] Detected PIPT I-cache on CPU1137machine # [ 0.006305] GICv3: CPU1: found redistributor 1 region 0:0x00000000080c0000138machine # [ 0.006377] GICv3: CPU1: using allocated LPI pending table @0x0000000045150000139machine # [ 0.006453] CPU1: Booted secondary processor 0x0000000001 [0xc00fac40]140machine # [ 0.006888] smp: Brought up 1 node, 2 CPUs141machine # [ 0.006906] SMP: Total of 2 processors activated.142machine # [ 0.006909] CPU: All CPU(s) started at EL1143machine # [ 0.006918] CPU features: detected: Branch Target Identification144machine # [ 0.006922] CPU features: detected: ARMv8.4 Translation Table Level145machine # [ 0.006925] CPU features: detected: Instruction cache invalidation not required for I/D coherence146machine # [ 0.006928] CPU features: detected: Data cache clean to the PoU not required for I/D coherence147machine # [ 0.006932] CPU features: detected: Common not Private translations148machine # [ 0.006935] CPU features: detected: CRC32 instructions149machine # [ 0.006937] CPU features: detected: Data cache clean to Point of Deep Persistence150machine # [ 0.006941] CPU features: detected: Data cache clean to Point of Persistence151machine # [ 0.006943] CPU features: detected: Data independent timing control (DIT)152machine # [ 0.006946] CPU features: detected: E0PD153machine # [ 0.006948] CPU features: detected: Enhanced Counter Virtualization154machine # [ 0.006951] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF)155machine # [ 0.006954] CPU features: detected: Enhanced Virtualization Traps156machine # [ 0.006957] CPU features: detected: Fine Grained Traps157machine # [ 0.006960] CPU features: detected: Generic authentication (architected QARMA5 algorithm)158machine # [ 0.006964] CPU features: detected: RCpc load-acquire (LDAPR)159machine # [ 0.006966] CPU features: detected: LSE atomic instructions160machine # [ 0.006969] CPU features: detected: Privileged Access Never161machine # [ 0.006971] CPU features: detected: PMUv3162machine # [ 0.006974] CPU features: detected: RAS Extension Support163machine # [ 0.006976] CPU features: detected: RASv1p1 Extension Support164machine # [ 0.006978] CPU features: detected: Random Number Generator165machine # [ 0.006981] CPU features: detected: Speculation barrier (SB)166machine # [ 0.006983] CPU features: detected: Stage-2 Force Write-Back167machine # [ 0.006986] CPU features: detected: TLB range maintenance instructions168machine # [ 0.006989] CPU features: detected: Speculative Store Bypassing Safe (SSBS)169machine # [ 0.007049] alternatives: applying system-wide alternatives170machine # [ 0.010006] CPU features: detected: BBM Level 2 without TLB conflict abort171machine # [ 0.010186] Memory: 2944164K/3145728K available (24448K kernel code, 7094K rwdata, 26596K rodata, 4736K init, 1107K bss, 154876K reserved, 32768K cma-reserved)172machine # [ 0.011047] devtmpfs: initialized173machine # [ 0.013589] posixtimers hash table entries: 1024 (order: 2, 16384 bytes, linear)174machine # [ 0.013628] futex hash table entries: 512 (32768 bytes on 1 NUMA nodes, total 32 KiB, linear).175machine # [ 0.013838] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL176machine # [ 0.013846] 0 pages in range for non-PLT usage177machine # [ 0.013848] 508224 pages in range for PLT usage178machine # [ 0.013943] pinctrl core: initialized pinctrl subsystem179machine # [ 0.014915] DMI not present or invalid.180machine # [ 0.018181] NET: Registered PF_NETLINK/PF_ROUTE protocol family181machine # [ 0.020626] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations182machine # [ 0.020893] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations183machine # [ 0.021199] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations184machine # [ 0.021229] audit: initializing netlink subsys (disabled)185machine # [ 0.021676] audit: type=2000 audit(0.016:1): state=initialized audit_enabled=0 res=1186machine # [ 0.023071] thermal_sys: Registered thermal governor 'fair_share'187machine # [ 0.023077] thermal_sys: Registered thermal governor 'bang_bang'188machine # [ 0.023084] thermal_sys: Registered thermal governor 'step_wise'189machine # [ 0.023088] thermal_sys: Registered thermal governor 'user_space'190machine # [ 0.023093] thermal_sys: Registered thermal governor 'power_allocator'191machine # [ 0.023165] cpuidle: using governor ladder192machine # [ 0.023187] cpuidle: using governor menu193machine # [ 0.023622] hw-breakpoint: found 16 breakpoint and 4 watchpoint registers.194machine # [ 0.023680] ASID allocator initialised with 65536 entries195machine # [ 0.025656] Serial: AMBA PL011 UART driver196machine # [ 0.034821] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 13, base_baud = 0) is a PL011 rev1197machine # [ 0.035084] printk: console [ttyAMA0] enabled198machine # [ 0.058298] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages199machine # [ 0.058310] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page200machine # [ 0.058314] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages201machine # [ 0.058316] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page202machine # [ 0.058319] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages203machine # [ 0.058322] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page204machine # [ 0.058325] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages205machine # [ 0.058328] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page206machine # [ 0.063573] fbcon: Taking over console207machine # [ 0.063585] ACPI: Interpreter disabled.208machine # [ 0.064678] iommu: Default domain type: Translated209machine # [ 0.064683] iommu: DMA domain TLB invalidation policy: strict mode210machine # [ 0.067025] SCSI subsystem initialized211machine # [ 0.067356] usbcore: registered new interface driver usbfs212machine # [ 0.067383] usbcore: registered new interface driver hub213machine # [ 0.067404] usbcore: registered new device driver usb214machine # [ 0.067734] pps_core: LinuxPPS API ver. 1 registered215machine # [ 0.067738] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>216machine # [ 0.067747] PTP clock support registered217machine # [ 0.067788] EDAC MC: Ver: 3.0.0218machine # [ 0.068009] scmi_core: SCMI protocol bus registered219machine # [ 0.068545] FPGA manager framework220machine # [ 0.069328] vgaarb: loaded221machine # [ 0.071100] clocksource: Switched to clocksource arch_sys_counter222machine # [ 0.071796] VFS: Disk quotas dquot_6.6.0223machine # [ 0.071824] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)224machine # [ 0.074290] netfs: FS-Cache loaded225machine # [ 0.078253] pnp: PnP ACPI: disabled226machine # [ 0.081627] NET: Registered PF_INET protocol family227machine # [ 0.082155] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)228machine # [ 0.111548] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)229machine # [ 0.111596] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)230machine # [ 0.111636] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)231machine # [ 0.111776] TCP bind hash table entries: 32768 (order: 8, 1048576 bytes, linear)232machine # [ 0.112054] TCP: Hash tables configured (established 32768 bind 32768)233machine # [ 0.112172] MPTCP token hash table entries: 4096 (order: 5, 98304 bytes, linear)234machine # [ 0.112219] UDP hash table entries: 2048 (order: 5, 131072 bytes, linear)235machine # [ 0.112283] UDP-Lite hash table entries: 2048 (order: 5, 131072 bytes, linear)236machine # [ 0.112407] NET: Registered PF_UNIX/PF_LOCAL protocol family237machine # [ 0.112427] NET: Registered PF_XDP protocol family238machine # [ 0.112444] PCI: CLS 0 bytes, default 64239machine # [ 0.112732] Trying to unpack rootfs image as initramfs...240machine # [ 0.127619] kvm [1]: HYP mode not available241machine # [ 0.265294] Initialise system trusted keyrings242machine # [ 0.265455] workingset: timestamp_bits=42 max_order=20 bucket_order=0243machine # [ 0.265929] squashfs: version 4.0 (2009/01/31) Phillip Lougher244machine # [ 0.265979] 9p: Installing v9fs 9p2000 file system support245machine # [ 0.281026] Key type asymmetric registered246machine # [ 0.281034] Asymmetric key parser 'x509' registered247machine # [ 0.281142] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 242)248machine # [ 0.287187] io scheduler mq-deadline registered249machine # [ 0.287196] io scheduler kyber registered250machine # [ 0.303289] pl061_gpio 9030000.pl061: PL061 GPIO chip registered251machine # [ 0.311138] ledtrig-cpu: registered to indicate activity on CPUs252machine # [ 0.311706] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:253machine # [ 0.311736] pci-host-generic 4010000000.pcie: IO 0x003eff0000..0x003effffff -> 0x0000000000254machine # [ 0.311760] pci-host-generic 4010000000.pcie: MEM 0x0010000000..0x003efeffff -> 0x0010000000255machine # [ 0.311768] pci-host-generic 4010000000.pcie: MEM 0x8000000000..0xffffffffff -> 0x8000000000256machine # [ 0.311791] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits257machine # [ 0.311818] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]258machine # [ 0.311968] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00259machine # [ 0.311989] pci_bus 0000:00: root bus resource [bus 00-ff]260machine # [ 0.311994] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]261machine # [ 0.311998] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]262machine # [ 0.312002] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]263machine # [ 0.312135] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint264machine # [ 0.312756] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint265machine # [ 0.313013] pci 0000:00:01.0: BAR 0 [io 0x0000-0x001f]266machine # [ 0.313029] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff]267machine # [ 0.313064] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]268machine # [ 0.313080] pci 0000:00:01.0: ROM [mem 0x00000000-0x0003ffff pref]269machine # [ 0.313728] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint270machine # [ 0.313980] pci 0000:00:02.0: BAR 0 [io 0x0000-0x001f]271machine # [ 0.313995] pci 0000:00:02.0: BAR 1 [mem 0x00000000-0x00000fff]272machine # [ 0.314030] pci 0000:00:02.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]273machine # [ 0.314691] pci 0000:00:03.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint274machine # [ 0.314943] pci 0000:00:03.0: BAR 0 [io 0x0000-0x007f]275machine # [ 0.314958] pci 0000:00:03.0: BAR 1 [mem 0x00000000-0x00000fff]276machine # [ 0.314996] pci 0000:00:03.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]277machine # [ 0.323923] pci 0000:00:04.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint278machine # [ 0.324169] pci 0000:00:04.0: BAR 0 [io 0x0000-0x001f]279machine # [ 0.324184] pci 0000:00:04.0: BAR 1 [mem 0x00000000-0x00000fff]280machine # [ 0.324218] pci 0000:00:04.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]281machine # [ 0.324233] pci 0000:00:04.0: ROM [mem 0x00000000-0x0003ffff pref]282machine # [ 0.324859] pci 0000:00:05.0: [1af4:1050] type 00 class 0x038000 conventional PCI endpoint283machine # [ 0.325107] pci 0000:00:05.0: BAR 1 [mem 0x00000000-0x00000fff]284machine # [ 0.325141] pci 0000:00:05.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]285machine # [ 0.325764] pci 0000:00:06.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint286machine # [ 0.326013] pci 0000:00:06.0: BAR 1 [mem 0x00000000-0x00000fff]287machine # [ 0.326047] pci 0000:00:06.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]288machine # [ 0.326646] pci 0000:00:07.0: [8086:24cd] type 00 class 0x0c0320 conventional PCI endpoint289machine # [ 0.326887] pci 0000:00:07.0: BAR 0 [mem 0x00000000-0x00000fff]290machine # [ 0.327297] pci 0000:00:08.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint291machine # [ 0.327545] pci 0000:00:08.0: BAR 1 [mem 0x00000000-0x00000fff]292machine # [ 0.327579] pci 0000:00:08.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]293machine # [ 0.328202] pci 0000:00:09.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint294machine # [ 0.328447] pci 0000:00:09.0: BAR 1 [mem 0x00000000-0x00000fff]295machine # [ 0.328482] pci 0000:00:09.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]296machine # [ 0.329115] pci 0000:00:0a.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint297machine # [ 0.329365] pci 0000:00:0a.0: BAR 1 [mem 0x00000000-0x00000fff]298machine # [ 0.329399] pci 0000:00:0a.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]299machine # [ 0.330080] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint300machine # [ 0.330431] pci 0000:00:0b.0: BAR 0 [io 0x0000-0x003f]301machine # [ 0.330448] pci 0000:00:0b.0: BAR 1 [mem 0x00000000-0x00000fff]302machine # [ 0.330482] pci 0000:00:0b.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]303machine # [ 0.371290] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint304machine # [ 0.371556] pci 0000:00:0c.0: BAR 0 [io 0x0000-0x001f]305machine # [ 0.371570] pci 0000:00:0c.0: BAR 1 [mem 0x00000000-0x00000fff]306machine # [ 0.371597] pci 0000:00:0c.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]307machine # [ 0.372382] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned308machine # [ 0.372391] pci 0000:00:04.0: ROM [mem 0x10040000-0x1007ffff pref]: assigned309machine # [ 0.372394] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned310machine # [ 0.372449] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned311machine # [ 0.372500] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned312machine # [ 0.372552] pci 0000:00:04.0: BAR 4 [mem 0x800000c000-0x800000ffff 64bit pref]: assigned313machine # [ 0.372605] pci 0000:00:05.0: BAR 4 [mem 0x8000010000-0x8000013fff 64bit pref]: assigned314machine # [ 0.372656] pci 0000:00:06.0: BAR 4 [mem 0x8000014000-0x8000017fff 64bit pref]: assigned315machine # [ 0.372710] pci 0000:00:08.0: BAR 4 [mem 0x8000018000-0x800001bfff 64bit pref]: assigned316machine # [ 0.372758] pci 0000:00:09.0: BAR 4 [mem 0x800001c000-0x800001ffff 64bit pref]: assigned317machine # [ 0.372810] pci 0000:00:0a.0: BAR 4 [mem 0x8000020000-0x8000023fff 64bit pref]: assigned318machine # [ 0.372862] pci 0000:00:0b.0: BAR 4 [mem 0x8000024000-0x8000027fff 64bit pref]: assigned319machine # [ 0.372996] pci 0000:00:0c.0: BAR 4 [mem 0x8000028000-0x800002bfff 64bit pref]: assigned320machine # [ 0.373047] pci 0000:00:01.0: BAR 1 [mem 0x10080000-0x10080fff]: assigned321machine # [ 0.373066] pci 0000:00:02.0: BAR 1 [mem 0x10081000-0x10081fff]: assigned322machine # [ 0.373087] pci 0000:00:03.0: BAR 1 [mem 0x10082000-0x10082fff]: assigned323machine # [ 0.373105] pci 0000:00:04.0: BAR 1 [mem 0x10083000-0x10083fff]: assigned324machine # [ 0.373123] pci 0000:00:05.0: BAR 1 [mem 0x10084000-0x10084fff]: assigned325machine # [ 0.373141] pci 0000:00:06.0: BAR 1 [mem 0x10085000-0x10085fff]: assigned326machine # [ 0.373165] pci 0000:00:07.0: BAR 0 [mem 0x10086000-0x10086fff]: assigned327machine # [ 0.373186] pci 0000:00:08.0: BAR 1 [mem 0x10087000-0x10087fff]: assigned328machine # [ 0.373206] pci 0000:00:09.0: BAR 1 [mem 0x10088000-0x10088fff]: assigned329machine # [ 0.373224] pci 0000:00:0a.0: BAR 1 [mem 0x10089000-0x10089fff]: assigned330machine # [ 0.373247] pci 0000:00:0b.0: BAR 1 [mem 0x1008a000-0x1008afff]: assigned331machine # [ 0.373271] pci 0000:00:0c.0: BAR 1 [mem 0x1008b000-0x1008bfff]: assigned332machine # [ 0.373289] pci 0000:00:03.0: BAR 0 [io 0x1000-0x107f]: assigned333machine # [ 0.373307] pci 0000:00:0b.0: BAR 0 [io 0x1080-0x10bf]: assigned334machine # [ 0.373328] pci 0000:00:01.0: BAR 0 [io 0x10c0-0x10df]: assigned335machine # [ 0.373346] pci 0000:00:02.0: BAR 0 [io 0x10e0-0x10ff]: assigned336machine # [ 0.373364] pci 0000:00:04.0: BAR 0 [io 0x1100-0x111f]: assigned337machine # [ 0.373386] pci 0000:00:0c.0: BAR 0 [io 0x1120-0x113f]: assigned338machine # [ 0.373409] pci_bus 0000:00: resource 4 [io 0x0000-0xffff]339machine # [ 0.373414] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]340machine # [ 0.373417] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]341machine # [ 0.374482] pci 0000:00:07.0: enabling device (0000 -> 0002)342machine # [ 0.410841] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)343machine # [ 0.413264] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)344machine # [ 0.419978] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)345machine # [ 0.424103] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)346machine # [ 0.426374] virtio-pci 0000:00:05.0: enabling device (0000 -> 0002)347machine # [ 0.430753] virtio-pci 0000:00:06.0: enabling device (0000 -> 0002)348machine # [ 0.433793] virtio-pci 0000:00:08.0: enabling device (0000 -> 0002)349machine # [ 0.437550] virtio-pci 0000:00:09.0: enabling device (0000 -> 0002)350machine # [ 0.440601] virtio-pci 0000:00:0a.0: enabling device (0000 -> 0002)351machine # [ 0.442556] virtio-pci 0000:00:0b.0: enabling device (0000 -> 0003)352machine # [ 0.446655] virtio-pci 0000:00:0c.0: enabling device (0000 -> 0003)353machine # [ 0.455136] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled354machine # [ 0.456981] msm_serial: driver initialized355machine # [ 0.457180] SuperH (H)SCI(F) driver initialized356machine # [ 0.457241] STM32 USART driver initialized357machine # [ 0.478529] loop: module loaded358machine # [ 0.478920] virtio_blk virtio2: 2/0/0 default/read/poll queues359machine # [ 0.481499] virtio_blk virtio2: [vda] 16777216 512-byte logical blocks (8.59 GB/8.00 GiB)360machine # [ 0.485122] megasas: 07.734.00.00-rc1361machine # [ 0.485954] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]362machine # [ 0.489979] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000363machine # [ 0.490006] Intel/Sharp Extended Query Table at 0x0031364machine # [ 0.493896] Using buffer write method365machine # [ 0.493991] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]366machine # [ 0.497991] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000367machine # [ 0.498014] Intel/Sharp Extended Query Table at 0x0031368machine # [ 0.501436] Using buffer write method369machine # [ 0.501452] Concatenating MTD devices:370machine # [ 0.501455] (0): "0.flash"371machine # [ 0.501457] (1): "0.flash"372machine # [ 0.501459] into device "0.flash"373machine # [ 0.594621] Freeing initrd memory: 26968K374machine # [ 0.605186] tun: Universal TUN/TAP device driver, 1.6375machine # [ 0.610371] thunder_xcv, ver 1.0376machine # [ 0.610415] thunder_bgx, ver 1.0377machine # [ 0.610447] nicpf, ver 1.0378machine # [ 0.611506] e1000: Intel(R) PRO/1000 Network Driver379machine # [ 0.611513] e1000: Copyright (c) 1999-2006 Intel Corporation.380machine # [ 0.611562] e1000e: Intel(R) PRO/1000 Network Driver381machine # [ 0.611570] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.382machine # [ 0.611610] igb: Intel(R) Gigabit Ethernet Network Driver383machine # [ 0.611615] igb: Copyright (c) 2007-2014 Intel Corporation.384machine # [ 0.611647] igbvf: Intel(R) Gigabit Virtual Function Network Driver385machine # [ 0.611652] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.386machine # [ 0.611888] sky2: driver version 1.30387machine # [ 0.614826] usbcore: registered new interface driver usb-storage388machine # [ 0.614984] usbcore: registered new interface driver usbserial_generic389machine # [ 0.615006] usbserial: USB Serial support registered for generic390machine # [ 0.616039] ehci-pci 0000:00:07.0: EHCI Host Controller391machine # [ 0.616067] ehci-pci 0000:00:07.0: new USB bus registered, assigned bus number 1392machine # [ 0.616099] hv_vmbus: registering driver hyperv_keyboard393machine # [ 0.616317] ehci-pci 0000:00:07.0: irq 16, io mem 0x10086000394machine # [ 0.617619] rtc-pl031 9010000.pl031: registered as rtc0395machine # [ 0.617658] rtc-pl031 9010000.pl031: setting system clock to 2026-10-01T09:46:31 UTC (1790847991)396machine # [ 0.618205] i2c_dev: i2c /dev entries driver397machine # [ 0.623697] sdhci: Secure Digital Host Controller Interface driver398machine # [ 0.623708] sdhci: Copyright(c) Pierre Ossman399machine # [ 0.624174] Synopsys Designware Multimedia Card Interface Driver400machine # [ 0.624813] sdhci-pltfm: SDHCI platform and OF driver helper401machine # [ 0.627445] hid: raw HID events driver (C) Jiri Kosina402machine # [ 0.627966] usbcore: registered new interface driver usbhid403machine # [ 0.627973] usbhid: USB HID core driver404machine # [ 0.629760] ehci-pci 0000:00:07.0: USB 2.0 started, EHCI 1.00405machine # [ 0.630392] hub 1-0:1.0: USB hub found406machine # [ 0.630414] hub 1-0:1.0: 6 ports detected407machine # [ 0.631558] hw perfevents: enabled with armv8_pmuv3 PMU driver, 11 (0,800003ff) counters available408machine # [ 0.634277] drop_monitor: Initializing network drop monitor service409machine # [ 0.634548] NET: Registered PF_INET6 protocol family410machine # [ 0.635567] Segment Routing with IPv6411machine # [ 0.635617] In-situ OAM (IOAM) with IPv6412machine # [ 0.635709] NET: Registered PF_PACKET protocol family413machine # [ 0.635833] 9pnet: Installing 9P2000 support414machine # [ 0.635892] Key type dns_resolver registered415machine # [ 0.646181] registered taskstats version 1416machine # [ 0.646430] Loading compiled-in X.509 certificates417machine # [ 0.661406] Demotion targets for Node 0: null418machine # [ 0.661588] Key type .fscrypt registered419machine # [ 0.661594] Key type fscrypt-provisioning registered420machine # [ 0.661729] ima: No TPM chip found, activating TPM-bypass!421machine # [ 0.661749] ima: Allocated hash algorithm: sha1422machine # [ 0.661827] ima: No architecture policies found423machine # [ 0.662890] input: gpio-keys as /devices/platform/gpio-keys/input/input0424machine # [ 0.682538] clk: Disabling unused clocks425machine # [ 0.682558] PM: genpd: Disabling unused power domains426machine # [ 0.686034] Freeing unused kernel memory: 4736K427machine # [ 0.686231] Run /init as init process428machine # [ 0.715024] systemd[1]: Successfully made /usr/ read-only.429machine # [ 0.879180] usb 1-1: new high-speed USB device number 2 using ehci-pci430machine # [ 1.028852] input: QEMU QEMU USB Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:07.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input1431machine # [ 1.049426] 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)432machine # [ 1.049458] systemd[1]: Detected virtualization qemu.433machine # [ 1.049507] systemd[1]: Detected architecture arm64.434machine # [ 1.049515] systemd[1]: Running in initrd.435machine # [ 1.050077] systemd[1]: Initializing machine ID from random generator.436machine # [ 1.050236] systemd[1]: Hostname set to <machine>.437machine # [ 1.143147] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:07.0-1/input0438machine # [ 1.240896] systemd[1]: bpf-restrict-fs: LSM BPF program attached439machine # [ 1.263219] usb 1-2: new high-speed USB device number 3 using ehci-pci440machine # [ 1.308994] systemd[1]: Queued start job for default target Initrd Default Target.441machine # [ 1.318524] systemd[1]: Created slice Slice /system/modprobe.442machine # [ 1.318938] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.443machine # [ 1.318982] systemd[1]: Expecting device /dev/disk/by-label/nixos...444machine # [ 1.319016] systemd[1]: Reached target Path Units.445machine # [ 1.319038] systemd[1]: Reached target Slice Units.446machine # [ 1.319058] systemd[1]: Reached target Swaps.447machine # [ 1.319079] systemd[1]: Reached target Timer Units.448machine # [ 1.319393] systemd[1]: Listening on D-Bus System Message Bus Socket.449machine # [ 1.319591] systemd[1]: Listening on Journal Socket (/dev/log).450machine # [ 1.319763] systemd[1]: Listening on Journal Sockets.451machine # [ 1.319932] systemd[1]: Listening on udev Control Socket.452machine # [ 1.320033] systemd[1]: Listening on udev Kernel Socket.453machine # [ 1.320056] systemd[1]: Reached target Socket Units.454machine # [ 1.322281] systemd[1]: Starting Create List of Static Device Nodes...455machine # [ 1.322377] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs456machine # [ 1.328875] systemd[1]: Mounting Kernel Configuration File System...457machine # [ 1.355402] systemd[1]: Starting Journal Service...458machine # [ 1.360202] systemd[1]: Starting Load Kernel Modules...459machine # [ 1.360365] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os460machine # [ 1.363772] systemd[1]: Starting Coldplug All udev Devices...461machine # [ 1.383321] systemd[1]: Finished Create List of Static Device Nodes.462machine # [ 1.384580] systemd[1]: Mounted Kernel Configuration File System.463machine # [ 1.392804] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...464machine # [ 1.398819] [drm] pci: virtio-gpu-pci detected at 0000:00:05.0465machine # [ 1.399093] [drm] features: -virgl +edid -resource_blob -host_visible466machine # [ 1.399097] [drm] features: -context_init467machine # [ 1.400923] systemd-journald[79]: Collecting audit messages is disabled.468machine # [ 1.406141] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.469machine # [ 1.409065] [drm] number of scanouts: 1470machine # [ 1.409079] [drm] number of cap sets: 0471machine # [ 1.415776] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev472machine # [ 1.416616] virtio-pci 0000:00:05.0: [drm] Registered 1 planes with drm panic473machine # [ 1.416631] [drm] Initialized virtio_gpu 0.1.0 for 0000:00:05.0 on minor 0474machine # [ 1.427917] 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/input2475machine # [ 1.433148] hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:07.0-2/input0476machine # [ 1.448147] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.477machine # [ 1.459683] Console: switching to colour frame buffer device 160x50478machine # [ 1.463898] systemd[1]: Starting Create Static Device Nodes in /dev...479machine # [ 1.471703] virtio-pci 0000:00:05.0: [drm] fb0: virtio_gpudrmfb frame buffer device480machine # [ 1.485095] systemd[1]: Finished Load Kernel Modules.481machine # [ 1.487286] systemd[1]: Starting Apply Kernel Variables...482machine # [ 1.500232] systemd[1]: Finished Create Static Device Nodes in /dev.483machine # [ 1.500879] systemd[1]: Reached target Preparation for Local File Systems.484machine # [ 1.503245] systemd[1]: Reached target Local File Systems.485machine # [ 1.515888] systemd[1]: Starting Rule-based Manager for Device Events and Files...486machine # [ 1.517581] systemd-modules-load[80]: Using 2 probe threads487machine # [ 1.529079] systemd[1]: Started Journal Service.488machine # [ 1.529191] systemd-modules-load[80]: Module 'virtio_balloon' is built in489machine # [ 1.530780] systemd-modules-load[80]: Module 'virtio_console' is built in490machine # [ 1.536428] systemd-modules-load[80]: Inserted module 'dm_mod'491machine # [ 1.540626] systemd-modules-load[80]: Module 'virtio_rng' is built in492machine # [ 1.544389] systemd-modules-load[80]: Inserted module 'virtio_gpu'493machine # [ 1.545582] systemd[1]: Starting Create System Files and Directories...494machine # [ 1.552691] systemd-udevd[89]: Using default interface naming scheme 'v261'.495machine # [ 1.560708] systemd[1]: Finished Apply Kernel Variables.496machine # [ 1.584911] systemd[1]: Finished Create System Files and Directories.497machine # [ 1.593799] systemd[1]: Started Rule-based Manager for Device Events and Files.498machine # [ 1.626557] systemd[1]: Starting Virtual Console Setup...499machine # [ 1.684585] systemd-vconsole-setup[111]: Configuration of first virtual console was skipped, ignoring remaining ones.500machine # [ 1.688733] systemd[1]: Finished Virtual Console Setup.501machine # [ 2.108596] systemd[1]: Finished Coldplug All udev Devices.502machine # [ 2.110558] systemd[1]: Reached target System Initialization.503machine # [ 2.112400] systemd[1]: Reached target Basic System.504machine # [ 2.246830] (udev-worker)[123]: Network interface NamePolicy= disabled on kernel command line.505machine # [ 2.270894] (udev-worker)[104]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.506machine # [ 2.275756] (udev-worker)[104]: Network interface NamePolicy= disabled on kernel command line.507machine # [ 2.307418] systemd[1]: Found device /dev/disk/by-label/nixos.508machine # [ 2.308644] systemd[1]: Reached target Initrd Root Device.509machine # [ 2.312429] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos...510machine # [ 2.366470] systemd-fsck[129]: nixos: clean, 12/524288 files, 58513/2097152 blocks511machine # [ 2.372186] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos.512machine # [ 2.383147] systemd[1]: Mounting /sysroot...513machine # [ 2.411705] EXT4-fs (vda): mounted filesystem cedf17f9-9466-4f86-bae6-b91000bdaa13 r/w with ordered data mode. Quota mode: none.514machine # [ 2.416474] systemd[1]: Mounted /sysroot.515machine # [ 2.417294] systemd[1]: Reached target Initrd Root File System.516machine # [ 2.424818] systemd[1]: Starting Mountpoints Configured in the Real Root...517machine # [ 2.445171] systemd-sysroot-fstab-check[137]: /sysroot should be mounted in the initrd, will request daemon-reload.518machine # [ 2.448155] systemd[1]: Reload requested from client PID 137 ('systemd-sysroot') (unit initrd-parse-etc.service)...519machine # [ 2.452468] systemd[1]: Reloading...520machine # [ 2.602980] systemd[1]: Reloading finished in 152 ms.521machine # [ 2.647169] systemd-sysroot-fstab-check[137]: Requesting initrd-fs.target/start/replace...522machine # [ 2.650718] systemd-sysroot-fstab-check[137]: Requesting swap.target/start/replace...523machine # [ 2.653865] systemd[1]: initrd-parse-etc.service: Deactivated successfully.524machine # [ 2.656162] systemd[1]: Finished Mountpoints Configured in the Real Root.525machine # [ 2.657961] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies.526machine # [ 3.162190] fuse: init (API version 7.45)527machine # [ 3.168417] virtiofs virtio6: discovered new tag: nix-store528machine # [ 3.169351] virtiofs virtio6: virtio_fs_setup_dax: No cache capability529machine # [ 3.218237] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.530machine # [ 3.221624] systemd[1]: Stopped Virtual Console Setup.531machine # [ 3.224120] systemd[1]: Stopping Virtual Console Setup...532machine # [ 3.226872] systemd[1]: Starting Virtual Console Setup...533machine # [ 3.233014] virtiofs virtio7: discovered new tag: shared534machine # [ 3.238501] (udev-worker)[117]: mtd0ro: Failed to find and pin callout binary "/nix/store/gnadg5slifq2r638xvz4pv6vrsdl9xkj-systemd-261.2/lib/udev/mtd_probe": No such file or directory535machine # [ 3.242291] (udev-worker)[117]: mtd0ro: /etc/udev/rules.d/75-probe_mtd.rules:5 IMPORT{program}="mtd_probe $devnode": Failed to execute "mtd_probe /dev/mtd0ro", ignoring: No such file or directory536machine # [ 3.250305] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.537machine # [ 3.255562] virtiofs virtio7: virtio_fs_setup_dax: No cache capability538machine # [ 3.258779] virtiofs virtio8: discovered new tag: xchg539machine # [ 3.257942] systemd[1]: Stopped Virtual Console Setup.540machine # [ 3.260190] systemd[1]: Starting Virtual Console Setup...541machine # [ 3.264555] virtiofs virtio8: virtio_fs_setup_dax: No cache capability542machine # [ 3.292846] systemd-vconsole-setup[158]: Configuration of first virtual console was skipped, ignoring remaining ones.543machine # [ 3.294795] systemd[1]: Finished Virtual Console Setup.544machine # [ 3.367359] systemd[1]: Mounting /sysroot/nix/.ro-store...545machine # [ 3.372085] systemd[1]: Mounting /sysroot/nix/.rw-store...546machine # [ 3.394856] systemd[1]: Mounting /sysroot/run...547machine # [ 3.398044] systemd[1]: Mounting /sysroot/tmp/shared...548machine # [ 3.411707] systemd[1]: Mounting /sysroot/tmp/xchg...549machine # [ 3.421318] systemd[1]: Mounted /sysroot/nix/.ro-store.550machine # [ 3.423320] systemd[1]: Mounted /sysroot/nix/.rw-store.551machine # [ 3.428402] systemd[1]: Mounted /sysroot/run.552machine # [ 3.430733] systemd[1]: Starting rw-sysroot-nix-store.service...553machine # [ 3.439789] systemd[1]: Mounted /sysroot/tmp/xchg.554machine # [ 3.451778] systemd[1]: Mounted /sysroot/tmp/shared.555machine # [ 3.457596] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.556machine # [ 3.459056] systemd[1]: Finished rw-sysroot-nix-store.service.557machine # [ 4.365399] systemd[1]: Mounting /sysroot/nix/store...558machine # [ 4.412361] systemd[1]: Mounted /sysroot/nix/store.559machine # [ 4.413837] systemd[1]: Reached target Initrd File Systems.560machine # [ 4.417864] systemd[1]: Starting Find NixOS closure...561machine # [ 4.422554] systemd[1]: Starting Create Volatile Files and Directories in the Real Root...562machine # [ 4.453113] systemd[1]: Finished Create Volatile Files and Directories in the Real Root.563machine # [ 4.457961] systemd[1]: sysroot-run-credentials-systemd\x2dtmpfiles\x2dsetup\x2dsysroot.service.mount: Deactivated successfully.564machine # [ 4.461918] systemd[1]: Finished Find NixOS closure.565machine # [ 4.463167] systemd[1]: Reached target Initrd Default Target.566machine # [ 4.466290] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...567machine # [ 4.498193] systemd[1]: Stopped target Initrd Default Target.568machine # [ 4.500253] systemd[1]: Stopped target Basic System.569machine # [ 4.501592] systemd[1]: Stopped target Initrd Root Device.570machine # [ 4.502899] systemd[1]: Stopped target Path Units.571machine # [ 4.504389] systemd[1]: systemd-ask-password-console.path: Deactivated successfully.572machine # [ 4.506149] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.573machine # [ 4.508061] systemd[1]: Stopped target Slice Units.574machine # [ 4.509237] systemd[1]: Stopped target Socket Units.575machine # [ 4.510424] systemd[1]: Stopped target System Initialization.576machine # [ 4.511777] systemd[1]: Stopped target Swaps.577machine # [ 4.519468] systemd[1]: Stopped target Timer Units.578machine # [ 4.523943] systemd[1]: dbus.socket: Deactivated successfully.579machine # [ 4.528457] systemd[1]: Closed D-Bus System Message Bus Socket.580machine # [ 4.531349] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully.581machine # [ 4.536569] systemd[1]: Stopped Find NixOS closure.582machine # [ 4.540308] systemd[1]: Starting rw-sysroot-nix-store.service...583machine # [ 4.541861] systemd[1]: systemd-sysctl.service: Deactivated successfully.584machine # [ 4.543085] systemd[1]: Stopped Apply Kernel Variables.585machine # [ 4.544411] systemd[1]: systemd-modules-load.service: Deactivated successfully.586machine # [ 4.547415] systemd[1]: Stopped Load Kernel Modules.587machine # [ 4.549237] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully.588machine # [ 4.550613] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root.589machine # [ 4.551942] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.590machine # [ 4.553286] systemd[1]: Stopped Create System Files and Directories.591machine # [ 4.554374] systemd[1]: Stopped target Local File Systems.592machine # [ 4.555310] systemd[1]: Stopped target Preparation for Local File Systems.593machine # [ 4.556563] systemd[1]: systemd-udev-trigger.service: Deactivated successfully.594machine # [ 4.557672] systemd[1]: Stopped Coldplug All udev Devices.595machine # [ 4.558539] systemd[1]: Stopping Rule-based Manager for Device Events and Files...596machine # [ 4.559676] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.597machine # [ 4.560948] systemd[1]: Stopped Virtual Console Setup.598machine # [ 4.561753] systemd[1]: initrd-cleanup.service: Deactivated successfully.599machine # [ 4.562701] systemd[1]: Finished Cleaning Up and Shutting Down Daemons.600machine # [ 4.563955] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.601machine # [ 4.565138] systemd[1]: Finished rw-sysroot-nix-store.service.602machine # [ 4.566022] systemd[1]: systemd-udevd.service: Deactivated successfully.603machine # [ 4.566924] systemd[1]: Stopped Rule-based Manager for Device Events and Files.604machine # [ 4.567935] systemd[1]: systemd-udevd.service: Consumed 2.095s CPU time over 3.037s wall clock time, 28.6M memory peak.605machine # [ 4.569605] systemd[1]: systemd-udevd-control.socket: Deactivated successfully.606machine # [ 4.570636] systemd[1]: Closed udev Control Socket.607machine # [ 4.571433] systemd[1]: Starting Cleanup udev Database...608machine # [ 4.572626] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.609machine # [ 4.573773] systemd[1]: Stopped Create Static Device Nodes in /dev.610machine # [ 4.574717] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully.611machine # [ 4.575849] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully.612machine # [ 4.576942] systemd[1]: kmod-static-nodes.service: Deactivated successfully.613machine # [ 4.577932] systemd[1]: Stopped Create List of Static Device Nodes.614machine # [ 4.621308] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.615machine # [ 4.623314] systemd[1]: Finished Cleanup udev Database.616machine # [ 4.624709] systemd[1]: Reached target Switch Root.617machine # [ 4.628154] systemd[1]: Starting NixOS Activation...618machine # [ 4.747822] initrd-nixos-activation-start[193]: booting system configuration /nix/store/j73pylzh16dmx4531s4ra64gv96654f6-nixos-system-machine-test619machine # [ 4.792925] initrd-nixos-activation-start[193]: running activation script...620machine # [ 5.133541] initrd-nixos-activation-start[216]: setting up /etc...621machine # [ 5.281052] systemd[1]: initrd-nixos-activation.service: Deactivated successfully.622machine # [ 5.282371] systemd[1]: Finished NixOS Activation.623machine # [ 5.284306] systemd[1]: Starting Switch Root...624machine # [ 5.314535] systemd[1]: Switching root.625machine # [ 5.424946] systemd-journald[79]: Received SIGTERM from PID 1 (systemd).626machine # [ 6.288601] 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)627machine # [ 6.288666] systemd[1]: Detected virtualization qemu.628machine # [ 6.288738] systemd[1]: Detected architecture arm64.629machine # [ 6.288868] systemd[1]: Detected first boot.630machine # [ 6.291258] systemd[1]: Initializing machine ID from random generator.631machine # [ 6.489740] systemd[1]: bpf-restrict-fs: LSM BPF program attached632machine # [ 6.599071] systemd[1]: Applying preset policy.633machine # [ 6.845804] systemd[1]: Populated /etc with preset unit settings.634machine # [ 7.092565] systemd[1]: initrd-switch-root.service: Deactivated successfully.635machine # [ 7.093545] systemd[1]: Stopped initrd-switch-root.service.636machine # [ 7.096122] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.637machine # [ 7.099388] systemd[1]: Created slice Slice /system/getty.638machine # [ 7.101185] systemd[1]: Created slice User and Session Slice.639machine # [ 7.101849] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.640machine # [ 7.102503] systemd[1]: Started Forward Password Requests to Wall Directory Watch.641machine # [ 7.103172] systemd[1]: Expecting device /dev/hvc0...642machine # [ 7.103693] systemd[1]: Expecting device /dev/ttyAMA0...643machine # [ 7.104272] systemd[1]: Reached target Local Encrypted Volumes.644machine # [ 7.104874] systemd[1]: Stopped target initrd-fs.target.645machine # [ 7.105469] systemd[1]: Stopped target initrd-root-fs.target.646machine # [ 7.106024] systemd[1]: Stopped target initrd-switch-root.target.647machine # [ 7.106633] systemd[1]: Reached target Virtual Machines and Containers.648machine # [ 7.107251] systemd[1]: Reached target Path Units.649machine # [ 7.107779] systemd[1]: Reached target Remote File Systems.650machine # [ 7.108362] systemd[1]: Reached target Slice Units.651machine # [ 7.108993] systemd[1]: Reached target Swaps.652machine # [ 7.112986] systemd[1]: Listening on Query the User Interactively for a Password.653machine # [ 7.115542] systemd[1]: Listening on Process Core Dump Socket.654machine # [ 7.117322] systemd[1]: Listening on Credential Encryption/Decryption.655machine # [ 7.119214] systemd[1]: Listening on Factory Reset Management.656machine # [ 7.119704] systemd[1]: Listening on Hostname Service Socket.657machine # [ 7.125591] systemd[1]: Starting Journal Log Access Socket...658machine # [ 7.131563] systemd[1]: Listening on Journal Audit Socket.659machine # [ 7.134089] systemd[1]: Listening on Console Output Muting Service Socket.660machine # [ 7.135195] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.661machine # [ 7.135836] systemd[1]: TPM PCR Measurements skipped, unmet condition check ConditionSecurity=measured-os662machine # [ 7.137409] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki663machine # [ 7.142606] systemd[1]: Listening on Disk Repartitioning Service Socket.664machine # [ 7.143382] systemd[1]: Listening on udev Control Socket.665machine # [ 7.144089] systemd[1]: Listening on udev Varlink Socket.666machine # [ 7.149259] systemd[1]: Mounting Huge Pages File System...667machine # [ 7.154151] systemd[1]: Mounting POSIX Message Queue File System...668machine # [ 7.164028] systemd[1]: Mounting Kernel Debug File System...669machine # [ 7.174867] systemd[1]: Mounting Kernel Trace File System...670machine # [ 7.182905] systemd[1]: Starting Create List of Static Device Nodes...671machine # [ 7.183478] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs672machine # [ 7.190498] systemd[1]: Mounting Kernel Configuration File System...673machine # [ 7.195052] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm674machine # [ 7.197548] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore675machine # [ 7.198210] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse676machine # [ 7.209677] systemd[1]: Mounting FUSE Control File System...677machine # [ 7.211082] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67678machine # [ 7.220501] systemd[1]: Starting Journal Service...679machine # [ 7.230641] systemd[1]: Starting Load Kernel Modules...680machine # [ 7.251036] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...681machine # [ 7.261915] systemd[1]: Starting Remount Root and Kernel File Systems...682machine # [ 7.262502] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os683machine # [ 7.272752] systemd[1]: Starting Coldplug All udev Devices...684machine # [ 7.276423] systemd[1]: Listening on Journal Log Access Socket.685machine # [ 7.277153] systemd[1]: Mounted POSIX Message Queue File System.686machine # [ 7.278018] systemd[1]: Mounted Kernel Trace File System.687machine # [ 7.282658] systemd[1]: Mounted Kernel Debug File System.688machine # [ 7.286364] systemd[1]: Mounted Huge Pages File System.689machine # [ 7.302149] systemd[1]: Mounted Kernel Configuration File System.690machine # [ 7.317545] systemd[1]: Mounted FUSE Control File System.691machine # [ 7.336745] systemd[1]: Finished Create List of Static Device Nodes.692machine # [ 7.342006] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...693machine # [ 7.357687] systemd-journald[286]: Collecting audit messages is enabled.694machine # [ 7.374871] systemd[1]: Queued start job for default target Multi-User System.695machine # [ 7.379529] systemd[1]: Started Journal Service.696machine # [ 7.381329] systemd[1]: systemd-journald.service: Deactivated successfully.697machine # [ 7.382676] systemd-modules-load[287]: Using 2 probe threads698machine # [ 7.383879] systemd-modules-load[287]: Module 'atkbd' is built in699machine # [ 7.385479] systemd-modules-load[287]: Module 'loop' is built in700machine # [ 7.386584] systemd[1]: Finished Load Kernel Modules.701machine # [ 7.396768] systemd[1]: Starting Apply Kernel Variables...702machine # [ 7.399478] EXT4-fs (vda): re-mounted cedf17f9-9466-4f86-bae6-b91000bdaa13.703machine # [ 7.412552] systemd[1]: Finished Remount Root and Kernel File Systems.704machine # [ 7.417327] systemd[1]: Listening on Disk Image Download Service Socket.705machine # [ 7.426872] systemd[1]: Starting Flush Journal to Persistent Storage...706machine # [ 7.433846] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore707machine # [ 7.443939] systemd[1]: Starting Load/Save OS Random Seed...708machine # [ 7.448330] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os709machine # [ 7.462766] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.710machine # [ 7.468791] systemd[1]: Starting Create Static Device Nodes in /dev...711machine # [ 7.478304] systemd-oomd[289]: No swap; memory pressure usage will be degraded712machine # [ 7.486110] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.713machine # [ 7.497626] systemd-journald[286]: Received client request to flush runtime journal.714machine # [ 7.547778] systemd[1]: Finished Load/Save OS Random Seed.715machine # [ 7.551931] systemd[1]: Reached target First Boot Complete.716machine # [ 7.553894] systemd[1]: Finished Apply Kernel Variables.717machine # [ 7.554787] systemd[1]: Finished Flush Journal to Persistent Storage.718machine # [ 7.580450] systemd[1]: Finished Create Static Device Nodes in /dev.719machine # [ 7.581602] systemd[1]: Reached target Preparation for Local File Systems.720machine # [ 7.584735] systemd[1]: Starting Rule-based Manager for Device Events and Files...721machine # [ 7.639159] systemd-udevd[316]: Using default interface naming scheme 'v261'.722machine # [ 7.678059] systemd[1]: Started Rule-based Manager for Device Events and Files.723machine # [ 8.100125] systemd[1]: Mounting /run/wrappers...724machine # [ 8.111271] systemd[1]: Finished Coldplug All udev Devices.725machine # [ 8.134581] systemd[1]: Mounted /run/wrappers.726machine # [ 8.136109] systemd[1]: Reached target Local File Systems.727machine # [ 8.139829] systemd[1]: Listening on Boot Loader Control Service Socket.728machine # [ 8.143103] systemd[1]: Starting register-nix-paths.service...729machine # [ 8.146647] systemd[1]: Starting Create SUID/SGID Wrappers...730machine # [ 8.147606] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.731machine # [ 8.151852] systemd[1]: Starting Save Transient machine-id to Disk...732machine # [ 8.159365] systemd[1]: Starting Create System Files and Directories...733machine # [ 8.239693] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs734machine # [ 8.266081] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse735machine # [ 8.273778] systemd[1]: Finished Create System Files and Directories.736machine # [ 8.281858] systemd[1]: Starting Rebuild Journal Catalog...737machine # [ 8.286726] systemd[1]: Starting Record System Boot/Shutdown in UTMP...738machine # [ 8.352903] systemd[1]: Finished Record System Boot/Shutdown in UTMP.739machine # [ 8.379748] systemd[1]: Finished Rebuild Journal Catalog.740machine # [ 8.384428] systemd[1]: Starting Update is Completed...741machine # [ 8.440573] systemd[1]: Finished Update is Completed.742machine # [ 8.511244] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.743machine # [ 8.516402] systemd[1]: Finished Save Transient machine-id to Disk.744machine # [ 8.523662] systemd[1]: Condition check resulted in /dev/hvc0 being skipped.745machine # [ 8.612809] systemd[1]: Condition check resulted in /dev/ttyAMA0 being skipped.746machine # [ 8.664855] (udev-worker)[340]: Network interface NamePolicy= disabled on kernel command line.747machine # [ 8.739227] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.748machine # [ 8.740731] systemd[1]: Finished Create SUID/SGID Wrappers.749machine # [ 8.751023] (udev-worker)[342]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.750machine # [ 8.754830] (udev-worker)[342]: Network interface NamePolicy= disabled on kernel command line.751machine # [ 8.806182] systemd[1]: Condition check resulted in Virtio network device being skipped.752machine # [ 8.808337] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore753machine # [ 8.812801] systemd[1]: Starting Create SUID/SGID Wrappers...754machine # [ 8.814588] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.755machine # [ 8.817388] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67756machine # [ 8.821699] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore757machine # [ 8.824982] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os758machine # [ 8.828210] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os759machine # [ 8.901991] mousedev: PS/2 mouse device common for all mice760machine # [ 8.930842] systemd[1]: Finished register-nix-paths.service.761machine # [ 9.191943] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.762machine # [ 9.194723] systemd[1]: Finished Create SUID/SGID Wrappers.763machine # [ 9.199133] systemd[1]: Reached target System Initialization.764machine # [ 9.201287] systemd[1]: Started Discard unused filesystem blocks once a week.765machine # [ 9.206884] systemd[1]: Started Daily Cleanup of Temporary Directories.766machine # [ 9.211795] systemd[1]: Reached target Timer Units.767machine # [ 9.213133] systemd[1]: Listening on D-Bus System Message Bus Socket.768machine # [ 9.219266] systemd[1]: Listening on Nix Daemon Socket.769machine # [ 9.226160] systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.770machine # [ 9.232539] systemd[1]: Reached target Socket Units.771machine # [ 9.233466] systemd[1]: Reached target Basic System.772machine # [ 9.234439] systemd[1]: Started backdoor.service.773machine # [ 9.240344] systemd[1]: Starting Import lastlog data into lastlog2 database...774machine # [ 9.252112] systemd[1]: Starting Name Service Cache Daemon (nsncd)...775machine # [ 9.253441] systemd[1]: Starting Post-Boot Actions...776machine # [ 9.254547] systemd[1]: Started Reset console on configuration changes.777machine # [ 9.255808] systemd[1]: Starting resolvconf update...778machine # [ 9.279131] systemd[1]: Started rustfs.service.779machine # [ 9.285318] systemd[1]: Starting rustfs-setup.service...780machine # [ 9.291548] systemd[1]: Starting D-Bus System Message Bus...781machine # [ 9.323340] systemd[1]: Finished Post-Boot Actions.782machine # [ 9.346919] systemd[1]: Started Name Service Cache Daemon (nsncd).783machine # connecting to host...784machine # [ 9.353645] nsncd[480]: Oct 01 09:46:40.219 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"785machine # [ 9.363097] systemd[1]: Reached target Host and Network Name Lookups.786machine # [ 9.367777] systemd[1]: Reached target User and Group Name Lookups.787machine # [ 9.371378] systemd[1]: Starting User Login Management...788machine: Guest shell says: b'Spawning backdoor root shell...\n'789machine: connected to guest root shell790machine: (connecting took 9.76 seconds)791machine: (finished: waiting for the VM to finish booting, in 10.47 seconds)792machine # [ 9.438280] systemd[1]: Finished Import lastlog data into lastlog2 database.793machine # [ 9.522087] dbus-broker-launch[487]: Looking up NSS user entry for 'systemd-timesync'...794machine # [ 9.537231] dbus-broker-launch[487]: NSS returned no entry for 'systemd-timesync'795machine # [ 9.543289] dbus-broker-launch[487]: Invalid user-name in /nix/store/7rk1l7vm612w5nnhdsq18is34jxr0icr-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"796machine # [ 9.561159] systemd-logind[495]: Watching system buttons on /dev/input/event1 (QEMU QEMU USB Keyboard)797machine # [ 9.575797] systemd-logind[495]: Watching system buttons on /dev/input/event0 (gpio-keys)798machine # [ 9.580961] systemd-logind[495]: New seat seat0.799machine # [ 9.581911] systemd[1]: Started User Login Management.800machine # [ 9.582733] systemd[1]: Starting linger-users.service...801machine # [ 9.589613] systemd[1]: Started D-Bus System Message Bus.802machine # [ 9.632647] dbus-broker-launch[487]: Ready803machine # [ 9.675938] systemd[1]: linger-users.service: Deactivated successfully.804machine # [ 9.679252] systemd[1]: Finished linger-users.service.805machine # [ 9.719508] systemd[1]: Stopped target Host and Network Name Lookups.806machine # [ 9.723160] systemd[1]: Stopping Host and Network Name Lookups...807machine # [ 9.726597] systemd[1]: Stopped target User and Group Name Lookups.808machine # [ 9.730420] systemd[1]: Stopping User and Group Name Lookups...809machine # [ 9.731480] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...810machine # [ 9.742825] systemd[1]: nscd.service: Deactivated successfully.811machine # [ 9.743930] systemd[1]: Stopped Name Service Cache Daemon (nsncd).812machine # [ 9.752311] systemd[1]: Starting Name Service Cache Daemon (nsncd)...813machine # [ 9.814959] systemd[1]: Started Name Service Cache Daemon (nsncd).814machine # [ 9.817971] systemd[1]: Reached target Host and Network Name Lookups.815machine # [ 9.820604] nsncd[581]: Oct 01 09:46:40.702 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"816machine # [ 9.824166] systemd[1]: Reached target User and Group Name Lookups.817machine # [ 9.852541] systemd[1]: Finished resolvconf update.818machine # [ 9.853508] systemd[1]: Reached target Preparation for Network.819machine # [ 9.858324] systemd[1]: Starting DHCP Client...820machine # [ 9.865076] systemd[1]: Starting Address configuration of eth1...821machine # [ 9.873972] systemd[1]: Starting Extra networking commands....822machine # [ 9.988999] network-addresses-eth1-start[613]: adding address 192.168.1.1/24... done823machine # [ 10.016630] network-addresses-eth1-start[613]: adding address 2001:db8:1::1/64... done824machine # [ 10.055993] systemd[1]: Finished Address configuration of eth1.825machine # [ 10.116530] dhcpcd[626]: dhcpcd-10.3.2 starting826machine # [ 10.133598] dhcpcd[662]: dev: loaded udev827machine # [ 10.157400] 8021q: 802.1Q VLAN Support v1.8828machine # [ 10.157776] 8021q: adding VLAN 0 to HW filter on device eth1829machine # [ 10.220594] cfg80211: Loading compiled-in X.509 certificates for regulatory database830machine # [ 10.247145] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'831machine # [ 10.247683] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'832machine # [ 10.249187] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2833machine # [ 10.249520] cfg80211: failed to load regulatory.db834machine # [ 10.292421] systemd[1]: Finished Extra networking commands..835machine # [ 10.294660] systemd[1]: Reached target Network.836machine # [ 10.295470] systemd[1]: Starting PostgreSQL Server...837machine # [ 10.297584] systemd[1]: Starting Permit User Sessions...838machine # [ 10.344751] 8021q: adding VLAN 0 to HW filter on device eth0839machine # [ 10.345148] dhcpcd[662]: eth0: waiting for carrier840machine # [ 10.347539] dhcpcd[662]: libudev: received NULL device841machine # [ 10.348938] dhcpcd[662]: libudev: received NULL device842machine # [ 10.349892] dhcpcd[662]: eth0: carrier acquired843machine # [ 10.366360] dhcpcd[662]: DUID 00:01:00:01:32:50:e8:81:52:54:00:12:34:56844machine # [ 10.367443] dhcpcd[662]: eth0: IAID 00:12:34:56845machine # [ 10.368209] dhcpcd[662]: eth0: adding address fe80::5054:ff:fe12:3456846machine # [ 10.369152] systemd[1]: Finished Permit User Sessions.847machine # [ 10.372000] systemd[1]: Started Getty on tty1.848machine # [ 10.375049] systemd[1]: Reached target Login Prompts.849machine # [ 10.562241] postgresql-pre-start[704]: The files belonging to this database system will be owned by user "postgres".850machine # [ 10.566729] postgresql-pre-start[704]: This user must also own the server process.851machine # [ 10.572224] postgresql-pre-start[704]: The database cluster will be initialized with locale "en_US.UTF-8".852machine # [ 10.576407] postgresql-pre-start[704]: The default database encoding has accordingly been set to "UTF8".853machine # [ 10.577923] postgresql-pre-start[704]: The default text search configuration will be set to "english".854machine # [ 10.579159] postgresql-pre-start[704]: Data page checksums are enabled.855machine # [ 10.582749] postgresql-pre-start[704]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok856machine # [ 10.590278] postgresql-pre-start[704]: creating subdirectories ... ok857machine # [ 10.591214] postgresql-pre-start[704]: selecting dynamic shared memory implementation ... posix858machine # [ 10.689510] input: QEMU Virtio Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:06.0/virtio5/input/input3859machine # [ 10.724104] postgresql-pre-start[704]: selecting default "max_connections" ... 100860machine # [ 10.853555] postgresql-pre-start[704]: selecting default "shared_buffers" ... 128MB861machine # [ 11.054472] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.862machine # [ 11.060852] systemd[1]: Starting Virtual Console Setup...863machine # [ 11.090853] systemd-logind[495]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)864machine # [ 11.204994] systemd-vconsole-setup[745]: Configuration of first virtual console was skipped, ignoring remaining ones.865machine # [ 11.211620] systemd[1]: Finished Virtual Console Setup.866machine # [ 11.557777] postgresql-pre-start[704]: selecting default time zone ... UTC867machine # [ 11.559573] postgresql-pre-start[704]: creating configuration files ... ok868machine # [ 11.643261] dhcpcd[662]: eth0: soliciting a DHCP lease869machine # [ 11.652800] dhcpcd[662]: eth0: offered 10.0.2.15 from 10.0.2.2870machine # [ 11.664811] dhcpcd[662]: eth0: probing address 10.0.2.15/24871machine # [ 11.834899] postgresql-pre-start[704]: running bootstrap script ... ok872machine # [ 12.386189] postgresql-pre-start[704]: performing post-bootstrap initialization ... ok873machine # [ 12.501059] postgresql-pre-start[704]: syncing data to disk ... ok874machine # [ 12.502662] postgresql-pre-start[704]: initdb: warning: enabling "trust" authentication for local connections875machine # [ 12.504868] postgresql-pre-start[704]: 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.876machine # [ 12.508362] postgresql-pre-start[704]: Success. You can now start the database server using:877machine # [ 12.510153] postgresql-pre-start[704]: pg_ctl -D /var/lib/postgresql/18 -l logfile start878machine # [ 12.646902] postgres[764]: [764] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit879machine # [ 12.650372] postgres[764]: [764] LOG: listening on IPv4 address "0.0.0.0", port 5432880machine # [ 12.651801] postgres[764]: [764] LOG: listening on IPv6 address "::", port 5432881machine # [ 12.653488] postgres[764]: [764] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"882machine # [ 12.662515] postgres[773]: [773] LOG: database system was shut down at 2026-10-01 09:46:43 GMT883machine # [ 12.671245] postgres[764]: [764] LOG: database system is ready to accept connections884machine # [ 12.673677] systemd[1]: Started PostgreSQL Server.885machine # [ 12.680249] systemd[1]: Starting PostgreSQL Setup Scripts...886machine # [ 12.861689] dhcpcd[662]: eth0: soliciting an IPv6 router887machine # [ 12.862946] dhcpcd[662]: eth0: Router Advertisement from fe80::2888machine # [ 12.864310] dhcpcd[662]: eth0: adding address fec0::5054:ff:fe12:3456/64889machine # [ 12.865907] dhcpcd[662]: eth0: adding route to fec0::/64890machine # [ 12.867255] dhcpcd[662]: eth0: adding default route via fe80::2891machine # [ 12.957543] postgresql-setup-start[784]: CREATE DATABASE892machine # [ 13.003067] postgresql-setup-start[798]: CREATE ROLE893machine # [ 13.022798] postgresql-setup-start[800]: ALTER DATABASE894machine # [ 13.028150] systemd[1]: Finished PostgreSQL Setup Scripts.895machine # [ 13.029325] systemd[1]: Reached target PostgreSQL.896machine # [ 17.146244] dhcpcd[662]: eth0: leased 10.0.2.15 for 86400 seconds897machine # [ 17.146533] dhcpcd[662]: eth0: adding route to 10.0.2.0/24898machine # [ 17.146608] dhcpcd[662]: eth0: adding default route via 10.0.2.2899machine # [ 17.294332] systemd[1]: Started DHCP Client.900machine # [ 17.295433] systemd[1]: Reached target Network is Online.901machine # [ 17.298833] systemd[1]: Starting k3s service...902machine # [ 17.358374] k3s[900]: time="2026-10-01T09:46:48Z" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock"903machine # [ 17.361077] k3s[900]: time="2026-10-01T09:46:48Z" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/5d85999ad517c8ade07834e45aaf9a85f85fcc88eac84337a49e52ac8f651083"904machine # [ 20.482526] rustfs-setup-start[913]: mb s3://niks3905machine # [ 20.488616] systemd[1]: Finished rustfs-setup.service.906machine # [ 21.346146] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Starting k3s 1.36.4+k3s1 (4dedb15b)"907machine # [ 21.375476] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Configuring sqlite3 database connection pooling: maxIdle=20, maxOpen=0, maxLifetime=0s, maxIdleTime=2m0s"908machine # [ 21.379735] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Kine built with sqlite from github.com/mattn/go-sqlite3 version 3.53.3"909machine # [ 21.382560] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Configuring database table schema and indexes, this may take a moment..."910machine # [ 21.391435] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Database tables and indexes are up to date"911machine # [ 21.393821] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Running startup VACUUM to reclaim disk space, this may take a moment..."912machine # [ 21.396718] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Startup VACUUM completed successfully"913machine # [ 21.399953] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Kine available at unix://kine.sock"914machine # [ 21.402024] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"915machine # [ 21.404922] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="Datastore connection validated successfully, proceeding with bootstrap data generation"916machine # [ 21.407776] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="generated self-signed CA certificate CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:52.28888302 +0000 UTC notAfter=2036-09-28 08:46:52.28888302 +0000 UTC"917machine # [ 21.412268] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"918machine # [ 21.418863] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=system:k3s-supervisor,O=system:masters signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"919machine # [ 21.424926] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"920machine # [ 21.432122] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"921machine # [ 21.435875] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=system:apiserver,O=system:masters signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"922machine # [ 21.443951] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"923machine # [ 21.451474] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="generated self-signed CA certificate CN=k3s-server-ca@1790848012: notBefore=2026-10-01 08:46:52.29422404 +0000 UTC notAfter=2036-09-28 08:46:52.29422404 +0000 UTC"924machine # [ 21.455843] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"925machine # [ 21.460863] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=kube-scheduler signed by CN=k3s-server-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"926machine # [ 21.465017] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=kube-controller-manager signed by CN=k3s-server-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"927machine # [ 21.470693] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="generated self-signed CA certificate CN=k3s-request-header-ca@1790848012: notBefore=2026-10-01 08:46:52.2972819 +0000 UTC notAfter=2036-09-28 08:46:52.2972819 +0000 UTC"928machine # [ 21.473970] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"929machine # [ 21.479148] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="generated self-signed CA certificate CN=etcd-server-ca@1790848012: notBefore=2026-10-01 08:46:52.29853024 +0000 UTC notAfter=2036-09-28 08:46:52.29853024 +0000 UTC"930machine # [ 21.483091] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"931machine # [ 21.490245] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="generated self-signed CA certificate CN=etcd-peer-ca@1790848012: notBefore=2026-10-01 08:46:52.29974552 +0000 UTC notAfter=2036-09-28 08:46:52.29974552 +0000 UTC"932machine # [ 21.494124] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"933machine # [ 21.496896] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"934machine # [ 21.507346] k3s[900]: time="2026-10-01T09:46:52Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1790848012: notBefore=2026-10-01 08:46:52 +0000 UTC notAfter=2027-10-01 08:46:52 +0000 UTC"935machine # [ 21.510137] k3s[900]: time="2026-10-01T09:46:52Z" level=warning msg="dynamiclistener [::]:6443: no cached certificate available for preload - deferring certificate load until storage initialization or first client request"936machine # [ 21.513409] k3s[900]: time="2026-10-01T09:46:52Z" 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__1133_4ee_3c9c_65cb-9cad56:fec0::1133:4ee:3c9c:65cb 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=3F7DA7FDEB637FF816EE2474D6CB2E31FCC8EDC8]"937machine # [ 22.820362] k3s[900]: time="2026-10-01T09:46:53Z" level=info msg="Password verified locally for node machine"938machine # [ 22.822866] k3s[900]: time="2026-10-01T09:46:53Z" level=info msg="certificate CN=machine signed by CN=k3s-server-ca@1790848012: notBefore=2026-10-01 08:46:53 +0000 UTC notAfter=2027-10-01 08:46:53 +0000 UTC"939machine # [ 23.242806] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="certificate CN=system:node:machine,O=system:nodes signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:54 +0000 UTC notAfter=2027-10-01 08:46:54 +0000 UTC"940machine # [ 23.356714] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:54 +0000 UTC notAfter=2027-10-01 08:46:54 +0000 UTC"941machine # [ 23.512234] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1790848012: notBefore=2026-10-01 08:46:54 +0000 UTC notAfter=2027-10-01 08:46:54 +0000 UTC"942machine # [ 23.651379] k3s[900]: time="2026-10-01T09:46:54Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:50588: runtime core not ready"943machine # [ 23.779573] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Module overlay was already loaded"944machine # [ 23.838961] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.945machine # [ 23.846616] Bridge firewalling registered946machine # [ 23.854242] k3s[900]: time="2026-10-01T09:46:54Z" level=warning msg="Failed to load kernel module iptable_nat with modprobe"947machine # [ 23.860324] k3s[900]: time="2026-10-01T09:46:54Z" level=warning msg="Failed to load kernel module iptable_filter with modprobe"948machine # [ 23.870066] k3s[900]: time="2026-10-01T09:46:54Z" level=warning msg="Failed to load kernel module nft-expr-counter with modprobe"949machine # [ 23.925897] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Set sysctl 'net/ipv4/conf/default/forwarding' to 1"950machine # [ 23.928937] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_max' to 131072"951machine # [ 23.931591] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400"952machine # [ 23.934457] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_close_wait' to 3600"953machine # [ 23.940271] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Set sysctl 'net/ipv4/conf/all/forwarding' to 1"954machine # [ 23.942467] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Polling for API server readiness: GET /readyz failed: the server is currently unable to handle the request"955machine # [ 23.945533] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Creating k3s-cert-monitor event broadcaster"956machine # [ 23.947514] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Connecting to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"957machine # [ 23.949698] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Saving cluster bootstrap data to datastore"958machine # [ 23.951474] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"959machine # [ 23.954686] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Connection to etcd is ready"960machine # [ 23.956275] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="ETCD server is now running"961machine # [ 23.957754] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Handling backend connection request [machine]"962machine # [ 23.959496] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"963machine # [ 23.961581] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Remotedialer connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"964machine # [ 23.963835] k3s[900]: time="2026-10-01T09:46:54Z" 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"965machine # [ 23.995072] k3s[900]: time="2026-10-01T09:46:54Z" 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"966machine # [ 24.002568] k3s[900]: time="2026-10-01T09:46:54Z" 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"967machine # [ 24.023683] k3s[900]: time="2026-10-01T09:46:54Z" 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"968machine # [ 24.032410] k3s[900]: I1001 09:46:54.849733 900 options.go:263] external host was not specified, using 10.0.2.15969machine # [ 24.034069] k3s[900]: I1001 09:46:54.855492 900 server.go:158] Version: v1.36.4+k3s1970machine # [ 24.035448] k3s[900]: I1001 09:46:54.855548 900 server.go:160] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""971machine # [ 24.037136] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log"972machine # [ 24.038987] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"973machine # [ 24.040854] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="To join server node to cluster: k3s server -s https://10.0.2.15:6443 -t ${SERVER_NODE_TOKEN}"974machine # [ 24.042937] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"975machine # [ 24.044905] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="To join agent node to cluster: k3s agent -s https://10.0.2.15:6443 -t ${AGENT_NODE_TOKEN}"976machine # [ 24.046958] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"977machine # [ 24.048532] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Run: k3s kubectl"978machine # [ 24.049596] k3s[900]: time="2026-10-01T09:46:54Z" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml"979machine # [ 24.206259] k3s[900]: time="2026-10-01T09:46:55Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:50636: runtime core not ready"980machine # [ 24.315395] k3s[900]: E1001 09:46:55.200697 900 options.go:205] The manifest file is empty, ignoring.981machine # [ 24.319747] k3s[900]: I1001 09:46:55.205107 900 shared_informer.go:381] "Waiting for caches to sync" controller="node_authorizer"982machine # [ 24.341357] k3s[900]: I1001 09:46:55.226658 900 shared_informer.go:402] "Waiting for caches to sync"983machine # [ 24.352141] k3s[900]: I1001 09:46:55.237056 900 plugins.go:157] Loaded 15 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,PodGroupProtection,RuntimeClass,DefaultIngressClass,PodTopologyLabels,MutatingAdmissionPolicy,MutatingAdmissionWebhook.984machine # [ 24.365576] k3s[900]: I1001 09:46:55.237127 900 plugins.go:160] Loaded 17 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,PodSecurity,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,ClusterTrustBundleAttest,CertificateSubjectRestriction,PodGroupWorkloadExists,NodeDeclaredFeatureValidator,JobValidation,PodResizeValidator,ValidatingAdmissionPolicy,ValidatingAdmissionWebhook,ResourceQuota.985machine # [ 24.376291] k3s[900]: I1001 09:46:55.243208 900 shared_informer.go:402] "Waiting for caches to sync"986machine # [ 24.377692] k3s[900]: I1001 09:46:55.244450 900 instance.go:240] Using reconciler: lease987machine # [ 24.378852] k3s[900]: I1001 09:46:55.260519 900 handler.go:304] Adding GroupVersion apiextensions.k8s.io v1 to ResourceManager988machine # [ 24.380471] k3s[900]: W1001 09:46:55.260558 900 genericapiserver.go:798] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources.989machine # [ 24.386442] k3s[900]: I1001 09:46:55.271788 900 cidrallocator.go:198] starting ServiceCIDR Allocator Controller990machine # [ 24.425295] k3s[900]: time="2026-10-01T09:46:55Z" 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"991machine # [ 24.483258] k3s[900]: I1001 09:46:55.368564 900 handler.go:304] Adding GroupVersion v1 to ResourceManager992machine # [ 24.485159] k3s[900]: I1001 09:46:55.370067 900 apis.go:112] API group "internal.apiserver.k8s.io" is not enabled, skipping.993machine # [ 24.522060] k3s[900]: I1001 09:46:55.407270 900 apis.go:112] API group "storagemigration.k8s.io" is not enabled, skipping.994machine # [ 24.624224] k3s[900]: I1001 09:46:55.505683 900 handler.go:304] Adding GroupVersion authentication.k8s.io v1 to ResourceManager995machine # [ 24.626029] k3s[900]: W1001 09:46:55.505765 900 genericapiserver.go:798] Skipping API authentication.k8s.io/v1beta1 because it has no resources.996machine # [ 24.627906] k3s[900]: W1001 09:46:55.505779 900 genericapiserver.go:798] Skipping API authentication.k8s.io/v1alpha1 because it has no resources.997machine # [ 24.632216] k3s[900]: I1001 09:46:55.506663 900 handler.go:304] Adding GroupVersion authorization.k8s.io v1 to ResourceManager998machine # [ 24.633873] k3s[900]: W1001 09:46:55.506697 900 genericapiserver.go:798] Skipping API authorization.k8s.io/v1beta1 because it has no resources.999machine # [ 24.635736] k3s[900]: I1001 09:46:55.508228 900 handler.go:304] Adding GroupVersion autoscaling v2 to ResourceManager1000machine # [ 24.641015] k3s[900]: I1001 09:46:55.509379 900 handler.go:304] Adding GroupVersion autoscaling v1 to ResourceManager1001machine # [ 24.642657] k3s[900]: I1001 09:46:55.523684 900 handler.go:304] Adding GroupVersion batch v1 to ResourceManager1002machine # [ 24.646670] k3s[900]: W1001 09:46:55.523741 900 genericapiserver.go:798] Skipping API batch/v1beta1 because it has no resources.1003machine # [ 24.648563] k3s[900]: I1001 09:46:55.525091 900 handler.go:304] Adding GroupVersion certificates.k8s.io v1 to ResourceManager1004machine # [ 24.650149] k3s[900]: W1001 09:46:55.525120 900 genericapiserver.go:798] Skipping API certificates.k8s.io/v1beta1 because it has no resources.1005machine # [ 24.652203] k3s[900]: W1001 09:46:55.525130 900 genericapiserver.go:798] Skipping API certificates.k8s.io/v1alpha1 because it has no resources.1006machine # [ 24.654110] k3s[900]: I1001 09:46:55.525958 900 handler.go:304] Adding GroupVersion coordination.k8s.io v1 to ResourceManager1007machine # [ 24.655691] k3s[900]: W1001 09:46:55.525984 900 genericapiserver.go:798] Skipping API coordination.k8s.io/v1beta1 because it has no resources.1008machine # [ 24.657627] k3s[900]: W1001 09:46:55.525992 900 genericapiserver.go:798] Skipping API coordination.k8s.io/v1alpha2 because it has no resources.1009machine # [ 24.659662] k3s[900]: I1001 09:46:55.530611 900 handler.go:304] Adding GroupVersion discovery.k8s.io v1 to ResourceManager1010machine # [ 24.661399] k3s[900]: W1001 09:46:55.530663 900 genericapiserver.go:798] Skipping API discovery.k8s.io/v1beta1 because it has no resources.1011machine # [ 24.663235] k3s[900]: I1001 09:46:55.535720 900 handler.go:304] Adding GroupVersion networking.k8s.io v1 to ResourceManager1012machine # [ 24.664986] k3s[900]: W1001 09:46:55.535781 900 genericapiserver.go:798] Skipping API networking.k8s.io/v1beta1 because it has no resources.1013machine # [ 24.666764] k3s[900]: I1001 09:46:55.536391 900 handler.go:304] Adding GroupVersion node.k8s.io v1 to ResourceManager1014machine # [ 24.668372] k3s[900]: W1001 09:46:55.536412 900 genericapiserver.go:798] Skipping API node.k8s.io/v1beta1 because it has no resources.1015machine # [ 24.670165] k3s[900]: W1001 09:46:55.536420 900 genericapiserver.go:798] Skipping API node.k8s.io/v1alpha1 because it has no resources.1016machine # [ 24.671873] k3s[900]: I1001 09:46:55.537310 900 handler.go:304] Adding GroupVersion policy v1 to ResourceManager1017machine # [ 24.673442] k3s[900]: W1001 09:46:55.537340 900 genericapiserver.go:798] Skipping API policy/v1beta1 because it has no resources.1018machine # [ 24.675067] k3s[900]: I1001 09:46:55.539300 900 handler.go:304] Adding GroupVersion rbac.authorization.k8s.io v1 to ResourceManager1019machine # [ 24.676840] k3s[900]: W1001 09:46:55.539344 900 genericapiserver.go:798] Skipping API rbac.authorization.k8s.io/v1beta1 because it has no resources.1020machine # [ 24.678625] k3s[900]: W1001 09:46:55.539355 900 genericapiserver.go:798] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources.1021machine # [ 24.680482] k3s[900]: I1001 09:46:55.539922 900 handler.go:304] Adding GroupVersion scheduling.k8s.io v1 to ResourceManager1022machine # [ 24.682012] k3s[900]: W1001 09:46:55.539944 900 genericapiserver.go:798] Skipping API scheduling.k8s.io/v1beta1 because it has no resources.1023machine # [ 24.683853] k3s[900]: W1001 09:46:55.539951 900 genericapiserver.go:798] Skipping API scheduling.k8s.io/v1alpha2 because it has no resources.1024machine # [ 24.685842] k3s[900]: I1001 09:46:55.543092 900 handler.go:304] Adding GroupVersion storage.k8s.io v1 to ResourceManager1025machine # [ 24.687355] k3s[900]: W1001 09:46:55.543152 900 genericapiserver.go:798] Skipping API storage.k8s.io/v1beta1 because it has no resources.1026machine # [ 24.689155] k3s[900]: W1001 09:46:55.543167 900 genericapiserver.go:798] Skipping API storage.k8s.io/v1alpha1 because it has no resources.1027machine # [ 24.690857] k3s[900]: I1001 09:46:55.544538 900 handler.go:304] Adding GroupVersion flowcontrol.apiserver.k8s.io v1 to ResourceManager1028machine # [ 24.692628] k3s[900]: W1001 09:46:55.544571 900 genericapiserver.go:798] Skipping API flowcontrol.apiserver.k8s.io/v1beta3 because it has no resources.1029machine # [ 24.694452] k3s[900]: W1001 09:46:55.544578 900 genericapiserver.go:798] Skipping API flowcontrol.apiserver.k8s.io/v1beta2 because it has no resources.1030machine # [ 24.696330] k3s[900]: W1001 09:46:55.544587 900 genericapiserver.go:798] Skipping API flowcontrol.apiserver.k8s.io/v1beta1 because it has no resources.1031machine # [ 24.698192] k3s[900]: I1001 09:46:55.548760 900 handler.go:304] Adding GroupVersion apps v1 to ResourceManager1032machine # [ 24.699674] k3s[900]: W1001 09:46:55.548810 900 genericapiserver.go:798] Skipping API apps/v1beta2 because it has no resources.1033machine # [ 24.701352] k3s[900]: W1001 09:46:55.548820 900 genericapiserver.go:798] Skipping API apps/v1beta1 because it has no resources.1034machine # [ 24.702913] k3s[900]: I1001 09:46:55.552022 900 handler.go:304] Adding GroupVersion admissionregistration.k8s.io v1 to ResourceManager1035machine # [ 24.704619] k3s[900]: W1001 09:46:55.552068 900 genericapiserver.go:798] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources.1036machine # [ 24.706462] k3s[900]: W1001 09:46:55.552079 900 genericapiserver.go:798] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources.1037machine # [ 24.708431] k3s[900]: I1001 09:46:55.552750 900 handler.go:304] Adding GroupVersion events.k8s.io v1 to ResourceManager1038machine # [ 24.709925] k3s[900]: W1001 09:46:55.552776 900 genericapiserver.go:798] Skipping API events.k8s.io/v1beta1 because it has no resources.1039machine # [ 24.711612] k3s[900]: I1001 09:46:55.555501 900 handler.go:304] Adding GroupVersion resource.k8s.io v1 to ResourceManager1040machine # [ 24.713217] k3s[900]: W1001 09:46:55.555542 900 genericapiserver.go:798] Skipping API resource.k8s.io/v1beta2 because it has no resources.1041machine # [ 24.714901] k3s[900]: W1001 09:46:55.555550 900 genericapiserver.go:798] Skipping API resource.k8s.io/v1beta1 because it has no resources.1042machine # [ 24.716737] k3s[900]: W1001 09:46:55.555554 900 genericapiserver.go:798] Skipping API resource.k8s.io/v1alpha3 because it has no resources.1043machine # [ 24.718447] k3s[900]: I1001 09:46:55.562857 900 handler.go:304] Adding GroupVersion apiregistration.k8s.io v1 to ResourceManager1044machine # [ 24.720053] k3s[900]: W1001 09:46:55.562901 900 genericapiserver.go:798] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources.1045machine # [ 25.023529] k3s[900]: time="2026-10-01T09:46:55Z" level=info msg="containerd is now running"1046machine # [ 25.030529] k3s[900]: time="2026-10-01T09:46:55Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/nixos/f8wk8zxfdgzjphcjhqwb7xq43dfrvbq4-niks3-server.tar"1047machine # [ 25.360144] k3s[900]: I1001 09:46:56.242493 900 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"1048machine # [ 25.362493] k3s[900]: I1001 09:46:56.242703 900 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"1049machine # [ 25.368199] k3s[900]: I1001 09:46:56.242945 900 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"1050machine # [ 25.371198] k3s[900]: I1001 09:46:56.243086 900 secure_serving.go:214] Serving securely on 127.0.0.1:64441051machine # [ 25.376169] k3s[900]: I1001 09:46:56.243227 900 tlsconfig.go:243] "Starting DynamicServingCertificateController"1052machine # [ 25.377641] k3s[900]: I1001 09:46:56.243299 900 system_namespaces_controller.go:66] Starting system namespaces controller1053machine # [ 25.379231] k3s[900]: I1001 09:46:56.243346 900 controller.go:87] "Starting OpenAPI AggregationController"1054machine # [ 25.380760] k3s[900]: I1001 09:46:56.243605 900 cluster_authentication_trust_controller.go:459] Starting cluster_authentication_trust_controller controller1055machine # [ 25.382666] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Waiting for caches to sync" logger=k3s1056machine # [ 25.388302] k3s[900]: I1001 09:46:56.243691 900 apf_controller.go:377] Starting API Priority and Fairness config controller1057machine # [ 25.389859] k3s[900]: I1001 09:46:56.243713 900 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"1058machine # [ 25.394293] k3s[900]: I1001 09:46:56.243814 900 local_available_controller.go:156] Starting LocalAvailability controller1059machine # [ 25.395998] k3s[900]: I1001 09:46:56.243823 900 cache.go:32] Waiting for caches to sync for LocalAvailability controller1060machine # [ 25.398970] k3s[900]: I1001 09:46:56.243991 900 customresource_discovery_controller.go:294] Starting DiscoveryController1061machine # [ 25.400835] k3s[900]: I1001 09:46:56.244020 900 remote_available_controller.go:434] Starting RemoteAvailability controller1062machine # [ 25.402336] k3s[900]: I1001 09:46:56.244028 900 cache.go:32] Waiting for caches to sync for RemoteAvailability controller1063machine # [ 25.404071] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Starting legacy_token_tracking_controller" logger=k3s1064machine # [ 25.405519] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Waiting for caches to sync" logger=k3s1065machine # [ 25.406844] k3s[900]: I1001 09:46:56.244220 900 aggregator.go:185] waiting for initial CRD sync...1066machine # [ 25.408290] k3s[900]: I1001 09:46:56.244279 900 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"1067machine # [ 25.410378] k3s[900]: I1001 09:46:56.244343 900 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"1068machine # [ 25.412773] k3s[900]: I1001 09:46:56.245177 900 controller.go:142] Starting OpenAPI controller1069machine # [ 25.413976] k3s[900]: I1001 09:46:56.245218 900 controller.go:90] Starting OpenAPI V3 controller1070machine # [ 25.415201] k3s[900]: I1001 09:46:56.245236 900 naming_controller.go:305] Starting NamingConditionController1071machine # [ 25.416761] k3s[900]: I1001 09:46:56.245287 900 nonstructuralschema_controller.go:202] Starting NonStructuralSchemaConditionController1072machine # [ 25.418502] k3s[900]: I1001 09:46:56.245314 900 apiapproval_controller.go:196] Starting KubernetesAPIApprovalPolicyConformantConditionController1073machine # [ 25.420430] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Starting CRDFinalizer" logger=k3s1074machine # [ 25.421760] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Starting apiserver lease garbage collector" logger=k3s1075machine # [ 25.423367] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Waiting for caches to sync" logger=k3s1076machine # [ 25.424956] k3s[900]: I1001 09:46:56.246073 900 storage_readiness_hook.go:70] Storage is ready for all registered resources1077machine # [ 25.426476] k3s[900]: I1001 09:46:56.247193 900 controller.go:89] "Starting OpenAPI V3 AggregationController"1078machine # [ 25.427953] k3s[900]: I1001 09:46:56.247240 900 controller.go:113] "Deleting old lease on startup" lease="kube-system/apiserver-ik4pcwfs7qgdl76byc4pomgvia"1079machine # [ 25.430144] k3s[900]: I1001 09:46:56.243309 900 apiservice_controller.go:100] Starting APIServiceRegistrationController1080machine # [ 25.431889] k3s[900]: I1001 09:46:56.247490 900 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller1081machine # [ 25.433808] k3s[900]: I1001 09:46:56.247734 900 repairip.go:210] Starting ipallocator-repair-controller1082machine # [ 25.435072] k3s[900]: I1001 09:46:56.247747 900 shared_informer.go:381] "Waiting for caches to sync" controller="ipallocator-repair-controller"1083machine # [ 25.436972] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg=Starting controller=kubernetes-service-cidr-controller logger=k3s1084machine # [ 25.438517] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Waiting for caches to sync" logger=k3s1085machine # [ 25.439757] k3s[900]: I1001 09:46:56.250442 900 crdregistration_controller.go:114] Starting crd-autoregister controller1086machine # [ 25.441428] k3s[900]: I1001 09:46:56.250460 900 shared_informer.go:381] "Waiting for caches to sync" controller="crd-autoregister"1087machine # [ 25.520204] k3s[900]: I1001 09:46:56.405520 900 shared_informer.go:388] "Caches are synced" controller="node_authorizer"1088machine # [ 25.545888] k3s[900]: I1001 09:46:56.431021 900 shared_informer.go:409] "Caches are synced"1089machine # [ 25.548255] k3s[900]: I1001 09:46:56.431086 900 policy_source.go:248] refreshing policies1090machine # [ 25.558949] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Caches are synced" logger=k3s1091machine # [ 25.561400] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Caches are synced" logger=k3s1092machine # [ 25.562756] k3s[900]: I1001 09:46:56.446224 900 shared_informer.go:409] "Caches are synced"1093machine # [ 25.565973] k3s[900]: I1001 09:46:56.446274 900 policy_source.go:248] refreshing policies1094machine # [ 25.567414] k3s[900]: I1001 09:46:56.448516 900 shared_informer.go:388] "Caches are synced" controller="ipallocator-repair-controller"1095machine # [ 25.571359] k3s[900]: I1001 09:46:56.449255 900 cache.go:39] Caches are synced for APIServiceRegistrationController controller1096machine # [ 25.573151] k3s[900]: I1001 09:46:56.449317 900 handler_discovery.go:459] Starting ResourceDiscoveryManager1097machine # [ 25.574751] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Caches are synced" logger=k3s1098machine # [ 25.575952] k3s[900]: I1001 09:46:56.450025 900 apf_controller.go:382] Running API Priority and Fairness config worker1099machine # [ 25.578335] k3s[900]: I1001 09:46:56.450045 900 apf_controller.go:385] Running API Priority and Fairness periodic rebalancing process1100machine # [ 25.581154] k3s[900]: I1001 09:46:56.450290 900 cache.go:39] Caches are synced for LocalAvailability controller1101machine # [ 25.582722] k3s[900]: I1001 09:46:56.450390 900 cache.go:39] Caches are synced for RemoteAvailability controller1102machine # [ 25.585883] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Caches are synced" logger=k3s1103machine # [ 25.588090] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Creating default ServiceCIDR" CIDRs="[10.43.0.0/16]" logger=k3s1104machine # [ 25.589663] k3s[900]: I1001 09:46:56.450698 900 shared_informer.go:388] "Caches are synced" controller="crd-autoregister"1105machine # [ 25.591278] k3s[900]: I1001 09:46:56.455294 900 aggregator.go:187] initial CRD sync complete...1106machine # [ 25.594673] k3s[900]: I1001 09:46:56.455323 900 autoregister_controller.go:144] Starting autoregister controller1107machine # [ 25.597387] k3s[900]: I1001 09:46:56.455334 900 cache.go:32] Waiting for caches to sync for autoregister controller1108machine # [ 25.598871] k3s[900]: I1001 09:46:56.455344 900 cache.go:39] Caches are synced for autoregister controller1109machine # [ 25.604282] k3s[900]: I1001 09:46:56.473383 900 controller.go:667] quota admission added evaluator for: leases.coordination.k8s.io1110machine # [ 25.605952] k3s[900]: I1001 09:46:56.486662 900 cidrallocator.go:302] created ClusterIP allocator for Service CIDR 10.43.0.0/161111machine # [ 25.607632] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Setting default ServiceCIDR condition Ready to True" logger=k3s1112machine # [ 25.640219] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Setting default ServiceCIDR condition Ready to True" logger=k3s1113machine # [ 25.646322] k3s[900]: I1001 09:46:56.531657 900 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161114machine # [ 25.713889] k3s[900]: I1001 09:46:56.598921 900 alloc.go:329] "allocated clusterIPs" service="default/kubernetes" clusterIPs={"IPv4":"10.43.0.1"}1115machine # [ 25.742250] k3s[900]: W1001 09:46:56.627556 900 lease.go:265] Resetting endpoints for master service "kubernetes" to [10.0.2.15]1116machine # [ 25.745137] k3s[900]: I1001 09:46:56.630487 900 controller.go:667] quota admission added evaluator for: endpoints1117machine # [ 25.759430] k3s[900]: I1001 09:46:56.644672 900 controller.go:667] quota admission added evaluator for: endpointslices.discovery.k8s.io1118machine # [ 25.786960] k3s[900]: E1001 09:46:56.672285 900 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 Service1119machine # [ 25.936933] k3s[900]: time="2026-10-01T09:46:56Z" level=info msg="Polling for API server readiness: GET /readyz failed: unknown"1120machine # [ 26.308862] k3s[900]: time="2026-10-01T09:46:57Z" level=info msg="Imported docker.io/library/niks3-server:1.4.0-aarch64-linux"1121machine # [ 26.313511] k3s[900]: time="2026-10-01T09:46:57Z" level=info msg="Tagged docker.io/library/niks3-server@sha256:d877ea25729d4dcf008a4e7c15ff20ae65165cbfd38e510681c88b876082972a"1122machine # [ 26.380152] k3s[900]: I1001 09:46:57.263347 900 storage_scheduling.go:137] created PriorityClass system-node-critical with value 20000010001123machine # [ 26.390293] k3s[900]: I1001 09:46:57.275624 900 storage_scheduling.go:137] created PriorityClass system-cluster-critical with value 20000000001124machine # [ 26.393136] k3s[900]: I1001 09:46:57.278093 900 storage_scheduling.go:153] all system priority classes are created successfully or already exist.1125machine # [ 26.403704] k3s[900]: time="2026-10-01T09:46:57Z" level=info msg="Imported 1 images from /var/lib/rancher/k3s/agent/images/nixos/f8wk8zxfdgzjphcjhqwb7xq43dfrvbq4-niks3-server.tar in 1.37356442s"1126machine # [ 26.407706] k3s[900]: time="2026-10-01T09:46:57Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/nixos/lf2s5pc8i15d9jlqqva8rkqqip46lm3k-k3s-airgap-images-arm64.tar.zst"1127machine # [ 26.532808] k3s[900]: time="2026-10-01T09:46:57Z" 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::1133:4ee:3c9c:65cb --node-labels= --read-only-port=0"1128machine # [ 27.387645] k3s[900]: I1001 09:46:58.272253 900 controller.go:667] quota admission added evaluator for: roles.rbac.authorization.k8s.io1129machine # [ 27.468062] k3s[900]: I1001 09:46:58.353101 900 controller.go:667] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io1130machine # [ 27.939747] k3s[900]: 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.1131machine # [ 27.958660] k3s[900]: time="2026-10-01T09:46:58Z" level=info msg="Creating k3s-supervisor event broadcaster"1132machine # [ 27.964455] k3s[900]: I1001 09:46:58.847128 900 server.go:541] "Kubelet version" kubeletVersion="v1.36.4+k3s1"1133machine # [ 27.965908] k3s[900]: I1001 09:46:58.847173 900 server.go:543] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1134machine # [ 27.967543] k3s[900]: I1001 09:46:58.847230 900 watchdog_linux.go:94] "Systemd watchdog is not enabled"1135machine # [ 27.969211] k3s[900]: I1001 09:46:58.847241 900 watchdog_linux.go:137] "Systemd watchdog is not enabled or the interval is invalid, so health checking will not be started."1136machine # [ 27.971508] k3s[900]: time="2026-10-01T09:46:58Z" level=info msg="Waiting for untainted node"1137machine # [ 27.972967] k3s[900]: time="2026-10-01T09:46:58Z" level=info msg="Kube API server is now running"1138machine # [ 27.974231] k3s[900]: time="2026-10-01T09:46:58Z" level=info msg="k3s is up and running"1139machine # [ 27.975812] systemd[1]: Started k3s service.1140machine # [ 27.976626] systemd[1]: Reached target Multi-User System.1141machine # [ 27.977580] systemd[1]: Startup finished in 686ms (kernel) + 5.118s (initrd) + 22.162s (userspace) = 27.967s.1142machine # [ 27.979980] k3s[900]: I1001 09:46:58.865259 900 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt"1143machine # [ 27.986187] k3s[900]: time="2026-10-01T09:46:58Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Node and Certificate Authority certificates managed by k3s are OK" object=machine reason=CertificateExpirationOK type=Normal1144machine # [ 28.010719] k3s[900]: E1001 09:46:58.896069 900 options.go:205] The manifest file is empty, ignoring.1145machine # [ 28.013436] k3s[900]: I1001 09:46:58.898675 900 server.go:1444] "Using cgroup driver setting received from the CRI runtime" cgroupDriver="systemd"1146machine # [ 28.016084] k3s[900]: I1001 09:46:58.901442 900 controllermanager.go:204] "Starting" version="v1.36.4+k3s1"1147machine # [ 28.017730] k3s[900]: I1001 09:46:58.901579 900 controllermanager.go:206] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1148machine # [ 28.021934] k3s[900]: I1001 09:46:58.902463 900 server.go:804] "--cgroups-per-qos enabled, but --cgroup-root was not specified. Defaulting to /"1149machine # [ 28.023767] k3s[900]: I1001 09:46:58.902502 900 server.go:865] "NoSwap is set due to memorySwapBehavior not specified" memorySwapBehavior="" FailSwapOn=false1150machine # [ 28.028367] k3s[900]: I1001 09:46:58.902802 900 container_manager_linux.go:273] "Container manager verified user specified cgroup-root exists" cgroupRoot=[]1151machine # [ 28.030411] k3s[900]: I1001 09:46:58.902850 900 container_manager_linux.go:278] "Creating Container Manager object based on Node Config" nodeConfig={"NodeName":"machine","RuntimeCgroupsName":"","SystemCgroupsName":"","KubeletCgroupsName":"","KubeletOOMScoreAdj":-999,"ContainerRuntime":"","CgroupsPerQOS":true,"CgroupRoot":"/","CgroupDriver":"systemd","KubeletRootDir":"/var/lib/kubelet","ProtectKernelDefaults":false,"KubeReservedCgroupName":"","SystemReservedCgroupName":"","ReservedSystemCPUs":{},"EnforceNodeAllocatable":{"pods":{}},"KubeReserved":null,"SystemReserved":null,"HardEvictionThresholds":[{"Signal":"imagefs.available","Operator":"LessThan","Value":{"Quantity":null,"Percentage":0.05},"GracePeriod":0,"MinReclaim":null},{"Signal":"nodefs.available","Operator":"LessThan","Value":{"Quantity":null,"Percentage":0.05},"GracePeriod":0,"MinReclaim":null}],"QOSReserved":{},"CPUManagerPolicy":"none","CPUManagerPolicyOptions":null,"TopologyManagerScope":"container","CPUManagerReconcilePeriod":10000000000,"MemoryManagerPolicy":"None","MemoryManagerReservedMemory":null,"MemoryReservationPolicy":"None","PodPidsLimit":-1,"EnforceCPULimits":true,"CPUCFSQuotaPeriod":100000000,"TopologyManagerPolicy":"none","TopologyManagerPolicyOptions":null,"CgroupVersion":2}1152machine # [ 28.050101] k3s[900]: I1001 09:46:58.903061 900 topology_manager.go:172] "Creating topology manager with none policy"1153machine # [ 28.052344] k3s[900]: I1001 09:46:58.903074 900 container_manager_linux.go:309] "Creating device plugin manager"1154machine # [ 28.059846] k3s[900]: I1001 09:46:58.903218 900 container_manager_linux.go:318] "Creating Dynamic Resource Allocation (DRA) manager"1155machine # [ 28.061972] k3s[900]: I1001 09:46:58.907623 900 state_mem.go:45] "Initialized" logger="CPUManager state memory"1156machine # [ 28.063706] k3s[900]: I1001 09:46:58.907871 900 kubelet.go:485] "Attempting to sync node with API server"1157machine # [ 28.065426] k3s[900]: I1001 09:46:58.907890 900 kubelet.go:386] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests"1158machine # [ 28.067562] k3s[900]: I1001 09:46:58.907918 900 kubelet.go:397] "Adding apiserver pod source"1159machine # [ 28.069741] k3s[900]: I1001 09:46:58.907934 900 apiserver.go:41] "Waiting for node sync before watching apiserver pods"1160machine # [ 28.071598] k3s[900]: I1001 09:46:58.915088 900 kuberuntime_manager.go:308] "Container runtime initialized" containerRuntime="containerd" version="2.3.4-k3s1.36" apiVersion="v1"1161machine # [ 28.074157] k3s[900]: I1001 09:46:58.916197 900 kubelet.go:1002] "Not starting ClusterTrustBundle informer because we are in static kubelet mode or the ClusterTrustBundleProjection featuregate is disabled"1162machine # [ 28.076959] k3s[900]: I1001 09:46:58.916229 900 kubelet.go:1029] "Not starting PodCertificateRequest manager because we are in static kubelet mode or the PodCertificateProjection feature gate is disabled"1163machine # [ 28.079622] k3s[900]: W1001 09:46:58.916326 900 probe.go:275] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating.1164machine # [ 28.081936] k3s[900]: I1001 09:46:58.934901 900 server.go:1280] "Started kubelet"1165machine # [ 28.083445] k3s[900]: I1001 09:46:58.939544 900 secure_serving.go:214] Serving securely on 127.0.0.1:102571166machine # [ 28.085779] k3s[900]: I1001 09:46:58.940246 900 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1167machine # [ 28.090868] k3s[900]: I1001 09:46:58.940271 900 shared_informer.go:402] "Waiting for caches to sync"1168machine # [ 28.092399] k3s[900]: I1001 09:46:58.940302 900 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"1169machine # [ 28.096700] k3s[900]: I1001 09:46:58.940421 900 tlsconfig.go:243] "Starting DynamicServingCertificateController"1170machine # [ 28.098577] k3s[900]: I1001 09:46:58.940492 900 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1171machine # [ 28.101546] k3s[900]: I1001 09:46:58.940507 900 shared_informer.go:402] "Waiting for caches to sync"1172machine # [ 28.104494] k3s[900]: I1001 09:46:58.940519 900 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1173machine # [ 28.107214] k3s[900]: I1001 09:46:58.940534 900 shared_informer.go:402] "Waiting for caches to sync"1174machine # [ 28.112291] k3s[900]: I1001 09:46:58.959293 900 fs_resource_analyzer.go:69] "Starting FS ResourceAnalyzer"1175machine # [ 28.113760] k3s[900]: I1001 09:46:58.970659 900 server.go:193] "Starting to listen" address="0.0.0.0" port=102501176machine # [ 28.115164] k3s[900]: I1001 09:46:58.972042 900 server.go:354] "Adding debug handlers to kubelet server"1177machine # [ 28.116679] k3s[900]: I1001 09:46:58.973446 900 ratelimit.go:56] "Setting rate limiting for endpoint" service="podresources" qps=100 burstTokens=101178machine # [ 28.118475] k3s[900]: I1001 09:46:58.973645 900 server_v1.go:49] "podresources" method="list" useActivePods=true1179machine # [ 28.119915] k3s[900]: I1001 09:46:58.973947 900 server.go:264] "Starting to serve the podresources API" endpoint="unix:/var/lib/kubelet/pod-resources/kubelet.sock"1180machine # [ 28.122402] k3s[900]: I1001 09:46:58.974705 900 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"1181machine # [ 28.125563] k3s[900]: I1001 09:46:58.974861 900 tlsconfig.go:243] "Starting DynamicServingCertificateController"1182machine # [ 28.127241] k3s[900]: I1001 09:46:58.984249 900 volume_manager.go:310] "Starting Kubelet Volume Manager"1183machine # [ 28.128839] k3s[900]: E1001 09:46:58.984631 900 kubelet_node_status.go:396] "Error getting the current node from lister" err="node \"machine\" not found"1184machine # [ 28.130904] k3s[900]: E1001 09:46:58.985003 900 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1185machine # [ 28.133430] k3s[900]: I1001 09:46:58.985455 900 desired_state_of_world_populator.go:146] "Desired state populator starts to run"1186machine # [ 28.135178] k3s[900]: I1001 09:46:58.986992 900 reconciler.go:29] "Reconciler: start to sync state"1187machine # [ 28.137337] k3s[900]: I1001 09:46:58.996971 900 factory.go:222] Registration of the systemd container factory successfully1188machine # [ 28.139015] k3s[900]: I1001 09:46:58.997188 900 factory.go:220] Registration of the crio container factory failed: Get "http://%2Fvar%2Frun%2Fcrio%2Fcrio.sock/info": dial unix /var/run/crio/crio.sock: connect: no such file or directory1189machine # [ 28.142696] k3s[900]: I1001 09:46:59.019314 900 factory.go:222] Registration of the containerd container factory successfully1190machine # [ 28.145854] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Creating embedded CRD addons.k3s.cattle.io"1191machine # [ 28.160052] k3s[900]: E1001 09:46:59.045390 900 kubelet.go:1725] "Image garbage collection failed once. Stats initialization may not have completed yet" err="invalid capacity 0 on image filesystem"1192machine # [ 28.182586] k3s[900]: E1001 09:46:59.067892 900 nodelease.go:50] "Failed to get node when trying to set owner ref to the node lease" err="nodes \"machine\" not found" node="machine"1193machine # [ 28.196151] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Creating embedded CRD etcdsnapshotfiles.k3s.cattle.io"1194machine # [ 28.197807] k3s[900]: I1001 09:46:59.082968 900 controller.go:667] quota admission added evaluator for: serviceaccounts1195machine # [ 28.199410] k3s[900]: E1001 09:46:59.084773 900 kubelet_node_status.go:396] "Error getting the current node from lister" err="node \"machine\" not found"1196machine # [ 28.204256] k3s[900]: E1001 09:46:59.088273 900 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1197machine # [ 28.212211] k3s[900]: I1001 09:46:59.097106 900 cpu_manager.go:235] "Starting" policy="none"1198machine # [ 28.214327] k3s[900]: I1001 09:46:59.097141 900 cpu_manager.go:236] "Reconciling" reconcilePeriod="10s"1199machine # [ 28.215890] k3s[900]: I1001 09:46:59.097189 900 state_mem.go:45] "Initialized" logger="CPUManager state checkpoint.CPUManager state memory"1200machine # [ 28.218396] k3s[900]: I1001 09:46:59.103746 900 policy_none.go:50] "Start"1201machine # [ 28.219574] k3s[900]: I1001 09:46:59.103860 900 memory_manager.go:190] "Starting memorymanager" policy="None"1202machine # [ 28.221218] k3s[900]: I1001 09:46:59.103890 900 state_mem.go:40] "Initializing new in-memory state store" logger="Memory Manager state checkpoint"1203machine # [ 28.222950] k3s[900]: I1001 09:46:59.106744 900 policy_none.go:44] "Start"1204machine # [ 28.247769] systemd[1]: Created slice libcontainer container kubepods.slice.1205machine # [ 28.256224] k3s[900]: I1001 09:46:59.141416 900 shared_informer.go:409] "Caches are synced"1206machine # [ 28.258993] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Creating embedded CRD helmchartconfigs.helm.cattle.io"1207machine # [ 28.263208] k3s[900]: I1001 09:46:59.146085 900 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1208machine # [ 28.272861] k3s[900]: I1001 09:46:59.146517 900 shared_informer.go:409] "Caches are synced"1209machine # [ 28.274651] k3s[900]: I1001 09:46:59.146538 900 shared_informer.go:409] "Caches are synced"1210machine # [ 28.300287] systemd[1]: Created slice libcontainer container kubepods-burstable.slice.1211machine # [ 28.304702] k3s[900]: E1001 09:46:59.190076 900 kubelet_node_status.go:396] "Error getting the current node from lister" err="node \"machine\" not found"1212machine # [ 28.312135] k3s[900]: E1001 09:46:59.192383 900 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1213machine # [ 28.318072] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Creating embedded CRD helmcharts.helm.cattle.io"1214machine # [ 28.321221] k3s[900]: I1001 09:46:59.194469 900 shared_informer.go:402] "Waiting for caches to sync"1215machine # [ 28.327856] systemd[1]: Created slice libcontainer container kubepods-besteffort.slice.1216machine # [ 28.359323] k3s[900]: E1001 09:46:59.244641 900 manager.go:525] "Failed to read data from checkpoint" err="checkpoint is not found" checkpoint="kubelet_internal_checkpoint"1217machine # [ 28.364380] k3s[900]: I1001 09:46:59.247486 900 eviction_manager.go:194] "Eviction manager: starting control loop"1218machine # [ 28.365868] k3s[900]: I1001 09:46:59.247509 900 container_log_manager.go:146] "Initializing container log rotate workers" workers=1 monitorPeriod="10s"1219machine # [ 28.367734] k3s[900]: I1001 09:46:59.248393 900 kubelet_network_linux.go:53] "Initialized iptables rules." protocol="IPv4"1220machine # [ 28.372393] k3s[900]: I1001 09:46:59.249168 900 plugin_manager.go:121] "Starting Kubelet Plugin Manager"1221machine # [ 28.387755] k3s[900]: I1001 09:46:59.272732 900 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1222machine # [ 28.393801] k3s[900]: E1001 09:46:59.279118 900 eviction_manager.go:272] "eviction manager: failed to check if we have separate container filesystem. Ignoring." err="no imagefs label for configured runtime"1223machine # [ 28.399605] k3s[900]: E1001 09:46:59.279209 900 eviction_manager.go:297] "Eviction manager: failed to get summary stats" err="failed to get node info: node \"machine\" not found"1224machine # [ 28.402734] k3s[900]: I1001 09:46:59.282362 900 kubelet_network_linux.go:53] "Initialized iptables rules." protocol="IPv6"1225machine # [ 28.406280] k3s[900]: I1001 09:46:59.282417 900 status_manager.go:277] "Starting to sync pod status with apiserver"1226machine # [ 28.408414] k3s[900]: I1001 09:46:59.282459 900 kubelet.go:2622] "Starting kubelet main sync loop"1227machine # [ 28.410521] k3s[900]: E1001 09:46:59.282515 900 kubelet.go:2646] "Skipping pod synchronization" err="PLEG is not healthy: pleg has yet to be successful"1228machine # [ 28.413559] k3s[900]: E1001 09:46:59.289959 900 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1229machine # [ 28.424107] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Waiting for CRD helmchartconfigs.helm.cattle.io to become available"1230machine # [ 28.452626] k3s[900]: I1001 09:46:59.337892 900 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1231machine # [ 28.468120] k3s[900]: I1001 09:46:59.353436 900 kubelet_node_status.go:75] "Attempting to register node" node="machine"1232machine # [ 28.472124] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Done waiting for CRD helmchartconfigs.helm.cattle.io to become available"1233machine # [ 28.474011] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available"1234machine # [ 28.499871] k3s[900]: E1001 09:46:59.385060 900 kubelet.go:3516] "Unable to register mirror pod because node is not registered yet" err="node \"machine\" not found" node="machine"1235machine # [ 28.512841] k3s[900]: I1001 09:46:59.398086 900 kubelet_node_status.go:78] "Successfully registered node" node="machine"1236machine # [ 28.514532] k3s[900]: E1001 09:46:59.398148 900 kubelet_node_status.go:479] "Error updating node status, will retry" err="error getting node \"machine\": node \"machine\" not found"1237machine # [ 28.517265] k3s[900]: I1001 09:46:59.402052 900 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1238machine # [ 28.522273] k3s[900]: I1001 09:46:59.407505 900 shared_informer.go:409] "Caches are synced"1239machine # [ 28.524423] k3s[900]: I1001 09:46:59.407558 900 server.go:228] "Successfully retrieved NodeIPs" NodeIPs=["10.0.2.15","fec0::1133:4ee:3c9c:65cb"]1240machine # [ 28.526528] k3s[900]: E1001 09:46:59.408377 900 server.go:265] "Kube-proxy configuration may be incomplete or incorrect" err="nodePortAddresses is unset; NodePort connections will be accepted on all local IPs. Consider using `--nodeport-addresses primary`"1241machine # [ 28.541235] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Annotations and labels have been set successfully on node: machine"1242machine # [ 28.543629] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Starting flannel with backend vxlan"1243machine # [ 28.572693] k3s[900]: I1001 09:46:59.457718 900 server.go:274] "kube-proxy running in dual-stack mode" primary ipFamily="IPv4"1244machine # [ 28.575011] k3s[900]: I1001 09:46:59.457819 900 server_linux.go:137] "Using iptables Proxier"1245machine # [ 28.605358] k3s[900]: I1001 09:46:59.490706 900 kubelet_node_status.go:431] "Fast updating node status as it just became ready"1246machine # [ 28.637556] k3s[900]: I1001 09:46:59.522030 900 proxier.go:241] "Setting route_localnet=1 to allow node-ports on localhost; to change this either disable iptables.localhostNodePorts (--iptables-localhost-nodeports) or set nodePortAddresses (--nodeport-addresses) to filter loopback addresses" ipFamily="IPv4"1247machine # [ 28.670844] k3s[900]: I1001 09:46:59.555834 900 server.go:539] "Version info" version="v1.36.4+k3s1"1248machine # [ 28.675252] k3s[900]: I1001 09:46:59.555881 900 server.go:541] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1249machine # [ 28.683043] k3s[900]: I1001 09:46:59.568421 900 config.go:200] "Starting service config controller"1250machine # [ 28.684777] k3s[900]: I1001 09:46:59.570181 900 shared_informer.go:381] "Waiting for caches to sync" controller="service config"1251machine # [ 28.688380] k3s[900]: I1001 09:46:59.573687 900 config.go:309] "Starting node config controller"1252machine # [ 28.689710] k3s[900]: I1001 09:46:59.573738 900 shared_informer.go:381] "Waiting for caches to sync" controller="node config"1253machine # [ 28.691299] k3s[900]: I1001 09:46:59.573782 900 shared_informer.go:388] "Caches are synced" controller="node config"1254machine # [ 28.695843] k3s[900]: I1001 09:46:59.570683 900 config.go:403] "Starting serviceCIDR config controller"1255machine # [ 28.697381] k3s[900]: I1001 09:46:59.573799 900 shared_informer.go:381] "Waiting for caches to sync" controller="serviceCIDR config"1256machine # [ 28.719750] k3s[900]: I1001 09:46:59.570618 900 config.go:106] "Starting endpoint slice config controller"1257machine # [ 28.724277] k3s[900]: I1001 09:46:59.606821 900 shared_informer.go:381] "Waiting for caches to sync" controller="endpoint slice config"1258machine # [ 28.793884] k3s[900]: I1001 09:46:59.679219 900 shared_informer.go:388] "Caches are synced" controller="service config"1259machine # [ 28.798459] k3s[900]: I1001 09:46:59.679781 900 shared_informer.go:388] "Caches are synced" controller="serviceCIDR config"1260machine # [ 28.827165] k3s[900]: I1001 09:46:59.712520 900 shared_informer.go:388] "Caches are synced" controller="endpoint slice config"1261machine: (finished: waiting for unit k3s.service, in 29.91 seconds)1262machine: waiting for unit rustfs-setup.service1263machine: (finished: waiting for unit rustfs-setup.service, in 0.06 seconds)1264machine: waiting for unit postgresql.service1265machine: (finished: waiting for unit postgresql.service, in 0.05 seconds)1266subtest: chart deploys and becomes ready1267??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1268 File "/nix/store/iiab4a2pmymr5lc22a6yc0d0fyf3g00n-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391269machine: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s1270??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1271 File "/nix/store/iiab4a2pmymr5lc22a6yc0d0fyf3g00n-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391272machine # [ 29.012374] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available"1273machine # [ 29.017724] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-40.1.4+up40.1.0.tgz"1274machine # [ 29.022439] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-40.1.4+up40.1.0.tgz"1275machine # [ 29.026112] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml"1276machine # [ 29.029803] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml"1277machine # [ 29.033385] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml"1278machine # [ 29.040299] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml"1279machine # [ 29.043793] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/runtimes.yaml"1280machine # [ 29.049094] k3s[900]: time="2026-10-01T09:46:59Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml"1281machine # [ 29.050798] k3s[900]: I1001 09:46:59.920913 900 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="podcertificaterequest-cleaner-controller" requiredFeatureGates=["PodCertificateRequest"]1282machine # [ 29.060340] k3s[900]: I1001 09:46:59.920982 900 controllermanager.go:641] "Warning: skipping controller" controller="podcertificaterequest-cleaner-controller"1283machine # [ 29.062376] k3s[900]: I1001 09:46:59.920992 900 controllermanager.go:689] "Warning: controller is disabled" controller="bootstrap-signer-controller"1284machine # [ 29.064271] k3s[900]: I1001 09:46:59.929654 900 apiserver.go:51] "Watching apiserver"1285machine # [ 29.065709] k3s[900]: I1001 09:46:59.943247 900 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller" requiredFeatureGates=["ClusterTrustBundle"]1286machine # [ 29.072414] k3s[900]: I1001 09:46:59.943277 900 controllermanager.go:641] "Warning: skipping controller" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller"1287machine # [ 29.231170] k3s[900]: time="2026-10-01T09:47:00Z" level=info msg="Starting dynamiclistener CN filter node controller with SANs: [127.0.0.1 ::1 localhost machine 10.0.2.15 fec0::1133:4ee:3c9c:65cb 10.43.0.1 kubernetes kubernetes.default kubernetes.default.svc kubernetes.default.svc.cluster.local]"1288machine # [ 29.238262] k3s[900]: time="2026-10-01T09:47:00Z" level=info msg="Tunnel server egress proxy mode: agent"1289machine # [ 29.302327] k3s[900]: I1001 09:47:00.186873 900 desired_state_of_world_populator.go:154] "Finished populating initial desired state of world"1290machine # [ 29.404749] k3s[900]: I1001 09:47:00.288505 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="controllerrevisions.apps"1291machine # [ 29.407272] k3s[900]: I1001 09:47:00.288659 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="addons.k3s.cattle.io"1292machine # [ 29.413207] k3s[900]: I1001 09:47:00.288795 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="deployments.apps"1293machine # [ 29.417719] k3s[900]: I1001 09:47:00.288834 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="horizontalpodautoscalers.autoscaling"1294machine # [ 29.422156] k3s[900]: I1001 09:47:00.288870 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="networkpolicies.networking.k8s.io"1295machine # [ 29.428346] k3s[900]: I1001 09:47:00.288926 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="cronjobs.batch"1296machine # [ 29.430632] k3s[900]: I1001 09:47:00.288959 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="jobs.batch"1297machine # [ 29.434488] k3s[900]: I1001 09:47:00.288991 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="ingresses.networking.k8s.io"1298machine # Error from server (NotFound): namespaces "niks3" not found1299machine # [ 29.440337] k3s[900]: I1001 09:47:00.289015 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="poddisruptionbudgets.policy"1300machine # [ 29.442757] k3s[900]: I1001 09:47:00.289040 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmchartconfigs.helm.cattle.io"1301machine # [ 29.447240] k3s[900]: I1001 09:47:00.289067 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmcharts.helm.cattle.io"1302machine # [ 29.450332] k3s[900]: I1001 09:47:00.289115 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="replicasets.apps"1303machine # [ 29.453211] k3s[900]: I1001 09:47:00.289138 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="statefulsets.apps"1304machine # [ 29.456540] k3s[900]: I1001 09:47:00.289183 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="leases.coordination.k8s.io"1305machine # [ 29.461430] k3s[900]: I1001 09:47:00.289224 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="limitranges"1306machine # [ 29.463720] k3s[900]: I1001 09:47:00.289271 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="roles.rbac.authorization.k8s.io"1307machine # [ 29.468142] k3s[900]: I1001 09:47:00.289298 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="serviceaccounts"1308machine # [ 29.470482] k3s[900]: I1001 09:47:00.289332 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="daemonsets.apps"1309machine # [ 29.472970] k3s[900]: I1001 09:47:00.289355 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="rolebindings.rbac.authorization.k8s.io"1310machine # [ 29.475436] k3s[900]: I1001 09:47:00.289377 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpointslices.discovery.k8s.io"1311machine # [ 29.478087] k3s[900]: I1001 09:47:00.289403 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="resourceclaimtemplates.resource.k8s.io"1312machine # [ 29.481551] k3s[900]: I1001 09:47:00.289436 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="csistoragecapacities.storage.k8s.io"1313machine # [ 29.484076] k3s[900]: I1001 09:47:00.295317 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpoints"1314machine # [ 29.486236] k3s[900]: I1001 09:47:00.295447 900 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="podtemplates"1315machine # [ 29.524113] k3s[900]: time="2026-10-01T09:47:00Z" level=info msg="Creating new TLS secret for kube-system/k3s-serving (count: 11): map[listener.cattle.io/cn-10.0.2.15:10.0.2.15 listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-__1-f16284:::1 listener.cattle.io/cn-fec0__1133_4ee_3c9c_65cb-9cad56:fec0::1133:4ee:3c9c:65cb 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=3F7DA7FDEB637FF816EE2474D6CB2E31FCC8EDC8]"1316machine # [ 29.542727] k3s[900]: time="2026-10-01T09:47:00Z" level=info msg="Active TLS secret kube-system/k3s-serving (ver=259) (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__1133_4ee_3c9c_65cb-9cad56:fec0::1133:4ee:3c9c:65cb 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=3F7DA7FDEB637FF816EE2474D6CB2E31FCC8EDC8]"1317machine # [ 30.130632] k3s[900]: I1001 09:47:01.015952 900 controllermanager.go:641] "Warning: skipping controller" controller="storage-version-migrator-controller"1318machine # [ 30.229551] k3s[900]: I1001 09:47:01.114683 900 node_lifecycle_controller.go:402] "Controller will reconcile labels" logger="node-lifecycle-controller"1319machine # [ 30.232260] k3s[900]: I1001 09:47:01.114776 900 controllermanager.go:689] "Warning: controller is disabled" controller="service-lb-controller"1320machine # [ 30.455499] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller"1321machine # [ 30.457336] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Creating deploy event broadcaster"1322machine # [ 30.471591] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Starting /v1, Kind=Node controller"1323machine # [ 30.478015] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Creating helm-controller event broadcaster"1324machine # [ 30.480691] k3s[900]: I1001 09:47:01.365890 900 controller.go:667] quota admission added evaluator for: addons.k3s.cattle.io1325machine # [ 30.555568] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" object=kube-system/ccm reason=ApplyingManifest type=Normal1326machine # [ 30.579941] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Labels and annotations have been set successfully on node: machine"1327machine # [ 30.585056] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Cluster dns configmap has been set successfully"1328machine # [ 30.744961] k3s[900]: I1001 09:47:01.630249 900 controllermanager.go:689] "Warning: controller is disabled" controller="cloud-node-lifecycle-controller"1329machine # Error from server (NotFound): namespaces "niks3" not found1330machine # [ 31.035101] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" object=kube-system/ccm reason=AppliedManifest type=Normal1331machine # [ 31.047348] k3s[900]: time="2026-10-01T09:47:01Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/ci.yaml\"" object=kube-system/ci reason=ApplyingManifest type=Normal1332machine # [ 31.344163] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ci.yaml\"" object=kube-system/ci reason=AppliedManifest type=Normal1333machine # [ 31.362080] k3s[900]: time="2026-10-01T09:47:02Z" 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=Normal1334machine # [ 31.512574] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported docker.io/rancher/klipper-helm:v0.13.3-build20260727"1335machine # [ 31.516708] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Tagged docker.io/rancher/klipper-helm@sha256:5425a2b4613d2458dbdff99218e8d487ebb59c20e7a941f061c0777070f0aac1"1336machine # [ 31.519589] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported docker.io/rancher/klipper-lb:v0.4.17"1337machine # [ 31.521744] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Tagged docker.io/rancher/klipper-lb@sha256:910944bb0bd94f060a82a56ca1ea1c577d3e49b3473a093a47a985f32e92d94a"1338machine # [ 31.524327] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported docker.io/rancher/local-path-provisioner:v0.0.37"1339machine # [ 31.540121] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Tagged docker.io/rancher/local-path-provisioner@sha256:e757967a5ec338f6a9b371c5a9688bedaa8c3578ea3dd4db329ea0084be0a86f"1340machine # [ 31.542680] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported docker.io/rancher/mirrored-coredns-coredns:1.14.6"1341machine # [ 31.544469] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Tagged docker.io/rancher/mirrored-coredns-coredns@sha256:900f9c109f7a33545d3c811516e8376df9019147b750f5ce3e254468769176ea"1342machine # [ 31.546853] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported docker.io/rancher/mirrored-library-busybox:1.37.0"1343machine # [ 31.550111] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Tagged docker.io/rancher/mirrored-library-busybox@sha256:101b4afd76732482eff9b95cae5f94bcf295e521fbec4e01b69c5421f3f3f3e5"1344machine # [ 31.553358] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported docker.io/rancher/mirrored-library-traefik:3.7.8"1345machine # [ 31.555278] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Tagged docker.io/rancher/mirrored-library-traefik@sha256:4299bbed850421258fc5448c2e0e6ad350981d4d335a68de11b92448aedbefe5"1346machine # [ 31.558321] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported docker.io/rancher/mirrored-metrics-server:v0.9.0"1347machine # [ 31.560256] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Tagged docker.io/rancher/mirrored-metrics-server@sha256:d9862115e7c7881280d3d75ca26bda8ffc0fc213315979575bf23ce9826205c0"1348machine # [ 31.562538] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported docker.io/rancher/mirrored-pause:3.10.2"1349machine # [ 31.564593] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Tagged docker.io/rancher/mirrored-pause@sha256:f548e0e8e3dc1896ca956272154dde3314e8cc4fde0a57577ee9fa1c63f5baf4"1350machine # [ 31.736986] k3s[900]: time="2026-10-01T09:47:02Z" level=info msg="Imported 8 images from /var/lib/rancher/k3s/agent/images/nixos/lf2s5pc8i15d9jlqqva8rkqqip46lm3k-k3s-airgap-images-arm64.tar.zst in 5.33293334s"1351machine # Error from server (NotFound): namespaces "niks3" not found1352machine # [ 32.083011] k3s[900]: I1001 09:47:02.968317 900 serving.go:417] Generated self-signed cert in-memory1353machine # [ 32.228336] k3s[900]: I1001 09:47:03.113638 900 serving.go:417] Generated self-signed cert in-memory1354machine # [ 32.403148] k3s[900]: I1001 09:47:03.288430 900 range_allocator.go:113] "No Secondary Service CIDR provided. Skipping filtering out secondary service addresses" logger="node-ipam-controller"1355machine # [ 32.408305] k3s[900]: I1001 09:47:03.291259 900 controllermanager.go:689] "Warning: controller is disabled" controller="node-route-controller"1356machine # [ 32.422946] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Starting rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding controller"1357machine # [ 32.434132] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Starting batch/v1, Kind=Job controller"1358machine # [ 32.435770] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Starting /v1, Kind=ConfigMap controller"1359machine # [ 32.440070] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Starting /v1, Kind=ServiceAccount controller"1360machine # [ 32.441559] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Starting /v1, Kind=Secret controller"1361machine # [ 32.452048] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller"1362machine # [ 32.453561] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller"1363machine # [ 32.464043] k3s[900]: I1001 09:47:03.345444 900 controllermanager.go:689] "Warning: controller is disabled" controller="selinux-warning-controller"1364machine # [ 32.476032] k3s[900]: I1001 09:47:03.360858 900 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="podgroup-protection-controller" requiredFeatureGates=["GenericWorkload"]1365machine # [ 32.478444] k3s[900]: I1001 09:47:03.360921 900 controllermanager.go:641] "Warning: skipping controller" controller="podgroup-protection-controller"1366machine # [ 32.517649] k3s[900]: I1001 09:47:03.402515 900 controllermanager.go:163] Version: v1.36.4+k3s11367machine # [ 32.519976] k3s[900]: I1001 09:47:03.405335 900 secure_serving.go:214] Serving securely on 127.0.0.1:102581368machine # [ 32.521634] k3s[900]: I1001 09:47:03.405995 900 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1369machine # [ 32.523550] k3s[900]: I1001 09:47:03.406018 900 shared_informer.go:402] "Waiting for caches to sync"1370machine # [ 32.525177] k3s[900]: I1001 09:47:03.406046 900 tlsconfig.go:243] "Starting DynamicServingCertificateController"1371machine # [ 32.526864] k3s[900]: I1001 09:47:03.406120 900 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1372machine # [ 32.529676] k3s[900]: I1001 09:47:03.406134 900 shared_informer.go:402] "Waiting for caches to sync"1373machine # [ 32.531216] k3s[900]: I1001 09:47:03.406146 900 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1374machine # [ 32.534140] k3s[900]: I1001 09:47:03.406162 900 shared_informer.go:402] "Waiting for caches to sync"1375machine # [ 32.535627] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Creating service-lb-controller event broadcaster"1376machine # [ 32.623695] k3s[900]: I1001 09:47:03.507148 900 shared_informer.go:409] "Caches are synced"1377machine # [ 32.625905] k3s[900]: I1001 09:47:03.507209 900 shared_informer.go:409] "Caches are synced"1378machine # [ 32.627770] k3s[900]: I1001 09:47:03.507182 900 shared_informer.go:409] "Caches are synced"1379machine # [ 32.681868] k3s[900]: I1001 09:47:03.567095 900 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="storageversion-garbage-collector-controller" requiredFeatureGates=["APIServerIdentity","StorageVersionAPI"]1380machine # [ 32.692437] k3s[900]: I1001 09:47:03.571955 900 controllermanager.go:641] "Warning: skipping controller" controller="storageversion-garbage-collector-controller"1381machine # [ 32.695483] k3s[900]: I1001 09:47:03.572018 900 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="resourcepoolstatusrequest-controller" requiredFeatureGates=["DRAResourcePoolStatus"]1382machine # [ 32.702607] k3s[900]: I1001 09:47:03.572042 900 controllermanager.go:641] "Warning: skipping controller" controller="resourcepoolstatusrequest-controller"1383machine # [ 32.705761] k3s[900]: I1001 09:47:03.575149 900 controller.go:667] quota admission added evaluator for: deployments.apps1384machine # [ 32.868175] k3s[900]: I1001 09:47:03.749705 900 legacy_serviceaccount_token_cleaner.go:103] "Starting legacy service account token cleaner controller"1385machine # [ 32.871177] k3s[900]: I1001 09:47:03.749757 900 shared_informer.go:402] "Waiting for caches to sync"1386machine # [ 32.873267] k3s[900]: I1001 09:47:03.750473 900 shared_informer.go:402] "Waiting for caches to sync"1387machine # [ 32.880193] k3s[900]: I1001 09:47:03.750565 900 endpoints_controller.go:193] "Starting endpoint controller"1388machine # [ 32.882186] k3s[900]: I1001 09:47:03.750581 900 shared_informer.go:402] "Waiting for caches to sync"1389machine # [ 32.883952] k3s[900]: I1001 09:47:03.750638 900 endpointslice_controller.go:280] "Starting endpoint slice controller"1390machine # [ 32.886069] k3s[900]: I1001 09:47:03.750652 900 shared_informer.go:402] "Waiting for caches to sync"1391machine # [ 32.887765] k3s[900]: I1001 09:47:03.750676 900 vac_protection_controller.go:206] "Starting VAC protection controller"1392machine # [ 32.892136] k3s[900]: I1001 09:47:03.750689 900 shared_informer.go:402] "Waiting for caches to sync"1393machine # [ 32.893814] k3s[900]: I1001 09:47:03.750752 900 controller.go:753] "Starting resource claim controller"1394machine # [ 32.895444] k3s[900]: I1001 09:47:03.750769 900 shared_informer.go:402] "Waiting for caches to sync"1395machine # [ 32.900030] k3s[900]: I1001 09:47:03.750792 900 shared_informer.go:402] "Waiting for caches to sync"1396machine # [ 32.901558] k3s[900]: I1001 09:47:03.750853 900 certificate_controller.go:120] "Starting certificate controller" name="csrapproving"1397machine # [ 32.903437] k3s[900]: I1001 09:47:03.750870 900 shared_informer.go:402] "Waiting for caches to sync"1398machine # [ 32.908108] k3s[900]: I1001 09:47:03.750901 900 expand_controller.go:328] "Starting expand controller"1399machine # [ 32.909525] k3s[900]: I1001 09:47:03.750916 900 shared_informer.go:402] "Waiting for caches to sync"1400machine # [ 32.910884] k3s[900]: I1001 09:47:03.750941 900 clusterroleaggregation_controller.go:176] "Starting ClusterRoleAggregator controller"1401machine # [ 32.915065] k3s[900]: I1001 09:47:03.750955 900 shared_informer.go:402] "Waiting for caches to sync"1402machine # [ 32.916496] k3s[900]: I1001 09:47:03.751000 900 device_taint_eviction.go:783] "Starting" controller="device-taint-eviction-controller" numWorkers=81403machine # [ 32.918295] k3s[900]: I1001 09:47:03.751137 900 namespace_controller.go:202] "Starting namespace controller"1404machine # [ 32.919677] k3s[900]: I1001 09:47:03.751152 900 shared_informer.go:402] "Waiting for caches to sync"1405machine # [ 32.928154] k3s[900]: I1001 09:47:03.751175 900 disruption.go:453] "Sending events to api server."1406machine # [ 32.929472] k3s[900]: I1001 09:47:03.751206 900 disruption.go:460] "Starting disruption controller"1407machine # [ 32.930732] k3s[900]: I1001 09:47:03.751215 900 shared_informer.go:402] "Waiting for caches to sync"1408machine # [ 32.932219] k3s[900]: I1001 09:47:03.751269 900 pv_controller_base.go:318] "Starting persistent volume controller"1409machine # [ 32.933657] k3s[900]: I1001 09:47:03.751284 900 shared_informer.go:402] "Waiting for caches to sync"1410machine # [ 32.934935] k3s[900]: I1001 09:47:03.751308 900 pv_protection_controller.go:81] "Starting PV protection controller"1411machine # [ 32.940149] k3s[900]: I1001 09:47:03.751322 900 shared_informer.go:402] "Waiting for caches to sync"1412machine # [ 32.941472] k3s[900]: I1001 09:47:03.751357 900 controller.go:174] "Starting ephemeral volume controller"1413machine # [ 32.942740] k3s[900]: I1001 09:47:03.751371 900 shared_informer.go:402] "Waiting for caches to sync"1414machine # [ 32.944220] k3s[900]: I1001 09:47:03.751424 900 replica_set.go:285] "Starting controller" name="replicationcontroller"1415machine # [ 32.945734] k3s[900]: I1001 09:47:03.751438 900 shared_informer.go:402] "Waiting for caches to sync"1416machine # [ 32.947117] k3s[900]: I1001 09:47:03.751680 900 serviceaccounts_controller.go:117] "Starting service account controller"1417machine # [ 32.948962] k3s[900]: I1001 09:47:03.751696 900 shared_informer.go:402] "Waiting for caches to sync"1418machine # [ 32.950224] k3s[900]: I1001 09:47:03.751753 900 daemon_controller.go:364] "Starting daemon sets controller"1419machine # [ 32.951571] k3s[900]: I1001 09:47:03.751769 900 shared_informer.go:402] "Waiting for caches to sync"1420machine # [ 32.952947] k3s[900]: I1001 09:47:03.751836 900 job_controller.go:336] "Starting job controller"1421machine # [ 32.954179] k3s[900]: I1001 09:47:03.751853 900 shared_informer.go:402] "Waiting for caches to sync"1422machine # [ 32.955509] k3s[900]: I1001 09:47:03.751907 900 taint_eviction.go:283] "Starting" controller="taint-eviction-controller"1423machine # [ 32.957122] k3s[900]: I1001 09:47:03.751951 900 taint_eviction.go:288] "Sending events to API server"1424machine # [ 32.958450] k3s[900]: I1001 09:47:03.751960 900 shared_informer.go:402] "Waiting for caches to sync"1425machine # [ 32.959707] k3s[900]: I1001 09:47:03.752000 900 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-legacy-unknown"1426machine # [ 32.961634] k3s[900]: I1001 09:47:03.752013 900 shared_informer.go:402] "Waiting for caches to sync"1427machine # [ 32.962874] k3s[900]: I1001 09:47:03.752055 900 node_lifecycle_controller.go:436] "Sending events to api server"1428machine # [ 32.964449] k3s[900]: I1001 09:47:03.752085 900 node_lifecycle_controller.go:443] "Starting node controller"1429machine # [ 32.966709] k3s[900]: I1001 09:47:03.752094 900 shared_informer.go:402] "Waiting for caches to sync"1430machine # [ 32.968141] k3s[900]: I1001 09:47:03.752145 900 endpointslicemirroring_controller.go:226] "Starting EndpointSliceMirroring controller"1431machine # [ 32.969830] k3s[900]: I1001 09:47:03.752161 900 shared_informer.go:402] "Waiting for caches to sync"1432machine # [ 32.971141] k3s[900]: I1001 09:47:03.752226 900 stateful_set.go:234] "Starting stateful set controller"1433machine # [ 32.972567] k3s[900]: I1001 09:47:03.752243 900 shared_informer.go:402] "Waiting for caches to sync"1434machine # [ 32.973818] k3s[900]: I1001 09:47:03.752278 900 cleaner.go:83] "Starting CSR cleaner controller"1435machine # [ 32.975024] k3s[900]: I1001 09:47:03.752331 900 ttl_controller.go:127] "Starting TTL controller"1436machine # [ 32.976332] k3s[900]: I1001 09:47:03.752347 900 shared_informer.go:402] "Waiting for caches to sync"1437machine # [ 32.977581] k3s[900]: I1001 09:47:03.752399 900 attach_detach_controller.go:334] "Starting attach detach controller"1438machine # [ 32.979107] k3s[900]: I1001 09:47:03.752413 900 shared_informer.go:402] "Waiting for caches to sync"1439machine # [ 32.980559] k3s[900]: I1001 09:47:03.752436 900 pvc_protection_controller.go:172] "Starting PVC protection controller"1440machine # [ 32.982001] k3s[900]: I1001 09:47:03.752449 900 shared_informer.go:402] "Waiting for caches to sync"1441machine # [ 32.983273] k3s[900]: I1001 09:47:03.752496 900 replica_set.go:285] "Starting controller" name="replicaset"1442machine # [ 32.984706] k3s[900]: I1001 09:47:03.752509 900 shared_informer.go:402] "Waiting for caches to sync"1443machine # [ 32.985950] k3s[900]: I1001 09:47:03.752529 900 tokencleaner.go:117] "Starting token cleaner controller"1444machine # [ 32.987290] k3s[900]: I1001 09:47:03.752543 900 shared_informer.go:402] "Waiting for caches to sync"1445machine # [ 32.988759] k3s[900]: I1001 09:47:03.752632 900 node_ipam_controller.go:142] "Starting ipam controller"1446machine # [ 32.990192] k3s[900]: I1001 09:47:03.752726 900 shared_informer.go:402] "Waiting for caches to sync"1447machine # [ 32.991658] k3s[900]: I1001 09:47:03.752753 900 ttlafterfinished_controller.go:112] "Starting TTL after finished controller"1448machine # [ 32.993421] k3s[900]: I1001 09:47:03.752775 900 shared_informer.go:402] "Waiting for caches to sync"1449machine # [ 32.994838] k3s[900]: I1001 09:47:03.752827 900 servicecidrs_controller.go:137] "Starting" controller="service-cidr-controller"1450machine # [ 32.996658] k3s[900]: I1001 09:47:03.752842 900 shared_informer.go:402] "Waiting for caches to sync"1451machine # [ 32.998044] k3s[900]: I1001 09:47:03.752981 900 horizontal.go:204] "Starting HPA controller"1452machine # [ 32.999345] k3s[900]: I1001 09:47:03.752994 900 shared_informer.go:402] "Waiting for caches to sync"1453machine # [ 33.000813] k3s[900]: I1001 09:47:03.753052 900 cronjob_controllerv2.go:143] "Starting cronjob controller v2"1454machine # [ 33.002346] k3s[900]: I1001 09:47:03.753065 900 shared_informer.go:402] "Waiting for caches to sync"1455machine # [ 33.003849] k3s[900]: I1001 09:47:03.753088 900 publisher.go:107] "Starting root CA cert publisher controller"1456machine # [ 33.005436] k3s[900]: I1001 09:47:03.753100 900 shared_informer.go:402] "Waiting for caches to sync"1457machine # [ 33.006826] k3s[900]: I1001 09:47:03.753290 900 device_taint_eviction.go:823] "Sending events to api server"1458machine # [ 33.008395] k3s[900]: I1001 09:47:03.753385 900 device_taint_eviction.go:1023] "Waiting" for="cache and event handler sync"1459machine # [ 33.013200] k3s[900]: I1001 09:47:03.753438 900 resource_quota_controller.go:297] "Starting resource quota controller"1460machine # [ 33.014768] k3s[900]: I1001 09:47:03.753453 900 shared_informer.go:402] "Waiting for caches to sync"1461machine # [ 33.016197] k3s[900]: I1001 09:47:03.761100 900 deployment_controller.go:180] "Starting controller" controller="deployment"1462machine # [ 33.017768] k3s[900]: I1001 09:47:03.761136 900 shared_informer.go:402] "Waiting for caches to sync"1463machine # [ 33.019078] k3s[900]: I1001 09:47:03.761196 900 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-serving"1464machine # [ 33.021071] k3s[900]: I1001 09:47:03.761213 900 shared_informer.go:402] "Waiting for caches to sync"1465machine # [ 33.022387] k3s[900]: I1001 09:47:03.761233 900 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-client"1466machine # [ 33.024254] k3s[900]: I1001 09:47:03.761245 900 shared_informer.go:402] "Waiting for caches to sync"1467machine # [ 33.025571] k3s[900]: I1001 09:47:03.761264 900 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kube-apiserver-client"1468machine # [ 33.027550] k3s[900]: I1001 09:47:03.761278 900 shared_informer.go:402] "Waiting for caches to sync"1469machine # [ 33.031423] k3s[900]: I1001 09:47:03.761305 900 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"1470machine # [ 33.037042] k3s[900]: I1001 09:47:03.761584 900 garbagecollector.go:141] "Starting controller" controller="garbagecollector"1471machine # [ 33.040807] k3s[900]: I1001 09:47:03.761608 900 shared_informer.go:402] "Waiting for caches to sync"1472machine # [ 33.043797] k3s[900]: I1001 09:47:03.761665 900 resource_quota_monitor.go:309] "QuotaMonitor running"1473machine # [ 33.045791] k3s[900]: I1001 09:47:03.761849 900 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"1474machine # [ 33.048687] k3s[900]: I1001 09:47:03.761943 900 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"1475machine # [ 33.051481] k3s[900]: I1001 09:47:03.762018 900 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"1476machine # [ 33.054610] k3s[900]: I1001 09:47:03.762378 900 graph_builder.go:387] "Running" component="GraphBuilder"1477machine # [ 33.064890] k3s[900]: I1001 09:47:03.763452 900 gc_controller.go:98] "Starting GC controller"1478machine # [ 33.066103] k3s[900]: I1001 09:47:03.763475 900 shared_informer.go:402] "Waiting for caches to sync"1479machine # [ 33.067393] k3s[900]: I1001 09:47:03.804281 900 shared_informer.go:402] "Waiting for caches to sync"1480machine # [ 33.072285] k3s[900]: I1001 09:47:03.813192 900 alloc.go:329] "allocated clusterIPs" service="kube-system/kube-dns" clusterIPs={"IPv4":"10.43.0.10"}1481machine # [ 33.074102] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/coredns.yaml\"" object=kube-system/coredns reason=AppliedManifest type=Normal1482machine # [ 33.084215] k3s[900]: I1001 09:47:03.908287 900 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.ResourceSlice"1483machine # [ 33.086352] k3s[900]: I1001 09:47:03.914813 900 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.ResourceClaim"1484machine # [ 33.090482] k3s[900]: I1001 09:47:03.914838 900 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.Pod"1485machine # [ 33.093938] k3s[900]: I1001 09:47:03.914847 900 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.ResourceSlice + event handler k8s.io/kubernetes/pkg/controller/devicetainteviction.(*Controller).Run"1486machine # [ 33.098841] k3s[900]: I1001 09:47:03.914859 900 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.ResourceClaim + event handler k8s.io/kubernetes/pkg/controller/devicetainteviction.(*Controller).Run"1487machine # [ 33.105789] k3s[900]: I1001 09:47:03.914867 900 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.Pod + event handler k8s.io/kubernetes/pkg/controller/devicetainteviction.(*Controller).Run"1488machine # [ 33.109123] k3s[900]: I1001 09:47:03.938199 900 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"1489machine # [ 33.113987] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Starting /v1, Kind=Node controller"1490machine # [ 33.115279] k3s[900]: I1001 09:47:03.963543 900 shared_informer.go:409] "Caches are synced"1491machine # [ 33.117029] k3s[900]: I1001 09:47:03.964060 900 shared_informer.go:409] "Caches are synced"1492machine # [ 33.118197] k3s[900]: I1001 09:47:03.964265 900 shared_informer.go:409] "Caches are synced"1493machine # [ 33.119363] k3s[900]: I1001 09:47:03.964300 900 shared_informer.go:409] "Caches are synced"1494machine # [ 33.120635] k3s[900]: I1001 09:47:03.964352 900 shared_informer.go:409] "Caches are synced"1495machine # [ 33.121786] k3s[900]: I1001 09:47:03.964442 900 shared_informer.go:409] "Caches are synced"1496machine # [ 33.124187] k3s[900]: I1001 09:47:03.964464 900 shared_informer.go:409] "Caches are synced"1497machine # [ 33.125392] k3s[900]: I1001 09:47:03.964525 900 shared_informer.go:409] "Caches are synced"1498machine # [ 33.126567] k3s[900]: I1001 09:47:03.964546 900 shared_informer.go:409] "Caches are synced"1499machine # [ 33.127733] k3s[900]: I1001 09:47:03.964584 900 shared_informer.go:409] "Caches are synced"1500machine # [ 33.132216] k3s[900]: I1001 09:47:03.964608 900 shared_informer.go:409] "Caches are synced"1501machine # [ 33.136126] k3s[900]: I1001 09:47:03.964669 900 shared_informer.go:409] "Caches are synced"1502machine # [ 33.140180] k3s[900]: I1001 09:47:03.964703 900 shared_informer.go:409] "Caches are synced"1503machine # [ 33.144164] k3s[900]: I1001 09:47:03.964787 900 shared_informer.go:409] "Caches are synced"1504machine # [ 33.145419] k3s[900]: I1001 09:47:03.964860 900 node_lifecycle_controller.go:1217] "Initializing eviction metric for zone" zone=""1505machine # [ 33.147027] k3s[900]: I1001 09:47:03.964941 900 node_lifecycle_controller.go:869] "Missing timestamp for Node. Assuming now as a timestamp" node="machine"1506machine # [ 33.151798] k3s[900]: I1001 09:47:03.964981 900 node_lifecycle_controller.go:1063] "Controller detected that zone is now in new state" zone="" newState="Normal"1507machine # [ 33.158028] k3s[900]: I1001 09:47:03.965038 900 shared_informer.go:409] "Caches are synced"1508machine # [ 33.159218] k3s[900]: time="2026-10-01T09:47:03Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Deferred node password secret validation complete" object=machine reason=NodePasswordValidationComplete type=Normal1509machine # [ 33.169215] k3s[900]: I1001 09:47:03.974328 900 shared_informer.go:409] "Caches are synced"1510machine # [ 33.176161] k3s[900]: I1001 09:47:03.974382 900 shared_informer.go:409] "Caches are synced"1511machine # [ 33.177400] k3s[900]: I1001 09:47:03.974399 900 shared_informer.go:409] "Caches are synced"1512machine # [ 33.178568] k3s[900]: I1001 09:47:03.974449 900 range_allocator.go:177] "Sending events to api server"1513machine # [ 33.179846] k3s[900]: I1001 09:47:03.974481 900 range_allocator.go:181] "Starting range CIDR allocator"1514machine # [ 33.185699] k3s[900]: I1001 09:47:03.974488 900 shared_informer.go:402] "Waiting for caches to sync"1515machine # [ 33.187012] k3s[900]: I1001 09:47:03.974494 900 shared_informer.go:409] "Caches are synced"1516machine # [ 33.192779] k3s[900]: I1001 09:47:03.974838 900 shared_informer.go:409] "Caches are synced"1517machine # [ 33.194003] k3s[900]: I1001 09:47:03.974877 900 shared_informer.go:409] "Caches are synced"1518machine # [ 33.195172] k3s[900]: I1001 09:47:03.974921 900 shared_informer.go:409] "Caches are synced"1519machine # [ 33.204172] k3s[900]: I1001 09:47:03.974945 900 shared_informer.go:409] "Caches are synced"1520machine # [ 33.205392] k3s[900]: I1001 09:47:03.978656 900 shared_informer.go:409] "Caches are synced"1521machine # [ 33.206538] k3s[900]: I1001 09:47:03.978702 900 shared_informer.go:409] "Caches are synced"1522machine # [ 33.207719] k3s[900]: I1001 09:47:03.978738 900 shared_informer.go:409] "Caches are synced"1523machine # [ 33.216162] k3s[900]: I1001 09:47:03.998991 900 device_taint_eviction.go:1023] "Done waiting" for="cache and event handler sync" instance="SharedIndexInformer *v1.DeviceClass"1524machine # [ 33.218291] k3s[900]: I1001 09:47:04.005948 900 shared_informer.go:409] "Caches are synced"1525machine # [ 33.219453] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Starting /v1, Kind=Pod controller"1526machine # [ 33.226170] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Starting apps/v1, Kind=DaemonSet controller"1527machine # [ 33.227623] k3s[900]: I1001 09:47:04.041155 900 controllermanager.go:338] Started "service-lb-controller"1528machine # [ 33.236143] k3s[900]: W1001 09:47:04.041191 900 controllermanager.go:315] "node-route-controller" is disabled1529machine # [ 33.237558] k3s[900]: I1001 09:47:04.041764 900 controllermanager.go:338] Started "cloud-node-controller"1530machine # [ 33.238862] k3s[900]: I1001 09:47:04.042040 900 controllermanager.go:338] Started "cloud-node-lifecycle-controller"1531machine # [ 33.240470] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Starting discovery.k8s.io/v1, Kind=EndpointSlice controller"1532machine # [ 33.248116] k3s[900]: I1001 09:47:04.053216 900 shared_informer.go:409] "Caches are synced"1533machine # [ 33.249457] k3s[900]: I1001 09:47:04.055426 900 node_controller.go:179] Sending events to api server.1534machine # [ 33.250746] k3s[900]: I1001 09:47:04.056124 900 node_lifecycle_controller.go:112] Sending events to api server1535machine # [ 33.253414] k3s[900]: I1001 09:47:04.060311 900 controller.go:235] Starting service controller1536machine # [ 33.255505] k3s[900]: I1001 09:47:04.060366 900 shared_informer.go:402] "Waiting for caches to sync"1537machine # [ 33.260229] k3s[900]: I1001 09:47:04.060898 900 node_controller.go:188] Waiting for informer caches to sync1538machine # [ 33.261579] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Adding node OwnerReference to node-password secret machine.node-password.k3s"1539machine # [ 33.263286] k3s[900]: I1001 09:47:04.074100 900 shared_informer.go:409] "Caches are synced"1540machine # [ 33.264614] k3s[900]: I1001 09:47:04.074183 900 shared_informer.go:409] "Caches are synced"1541machine # [ 33.267016] k3s[900]: I1001 09:47:04.074215 900 shared_informer.go:409] "Caches are synced"1542machine # [ 33.272386] k3s[900]: I1001 09:47:04.074248 900 shared_informer.go:409] "Caches are synced"1543machine # [ 33.273609] k3s[900]: I1001 09:47:04.075008 900 shared_informer.go:409] "Caches are synced"1544machine # [ 33.274783] k3s[900]: I1001 09:47:04.075369 900 shared_informer.go:409] "Caches are synced"1545machine # [ 33.276170] k3s[900]: I1001 09:47:04.075614 900 shared_informer.go:409] "Caches are synced"1546machine # [ 33.280387] k3s[900]: I1001 09:47:04.076366 900 shared_informer.go:409] "Caches are synced"1547machine # [ 33.281616] k3s[900]: I1001 09:47:04.085568 900 shared_informer.go:409] "Caches are synced"1548machine # [ 33.282921] k3s[900]: I1001 09:47:04.085761 900 shared_informer.go:409] "Caches are synced"1549machine # [ 33.284253] k3s[900]: I1001 09:47:04.085988 900 shared_informer.go:409] "Caches are synced"1550machine # [ 33.285459] k3s[900]: I1001 09:47:04.086148 900 shared_informer.go:409] "Caches are synced"1551machine # [ 33.286652] k3s[900]: I1001 09:47:04.086374 900 shared_informer.go:409] "Caches are synced"1552machine # [ 33.290501] k3s[900]: I1001 09:47:04.097577 900 shared_informer.go:409] "Caches are synced"1553machine # [ 33.296233] k3s[900]: I1001 09:47:04.098348 900 shared_informer.go:409] "Caches are synced"1554machine # [ 33.297685] k3s[900]: I1001 09:47:04.104870 900 shared_informer.go:402] "Waiting for caches to sync"1555machine # [ 33.299302] k3s[900]: I1001 09:47:04.149840 900 range_allocator.go:433] "Set node PodCIDR" node="machine" podCIDRs=["10.42.0.0/24"]1556machine # [ 33.318670] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Synced coredns NodeHosts entries for machine"1557machine # [ 33.396169] k3s[900]: I1001 09:47:04.278727 900 node_controller.go:432] Initializing node machine with cloud provider1558machine # [ 33.452305] k3s[900]: E1001 09:47:04.336185 900 options.go:205] The manifest file is empty, ignoring.1559machine # [ 33.459620] k3s[900]: I1001 09:47:04.344594 900 node_controller.go:477] Successfully initialized node machine with cloud provider1560machine # [ 33.462306] k3s[900]: I1001 09:47:04.347186 900 event.go:389] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="v1" type="Normal" reason="Synced" message="Node synced successfully"1561machine # [ 33.475601] k3s[900]: I1001 09:47:04.360615 900 shared_informer.go:409] "Caches are synced"1562machine # [ 33.487350] k3s[900]: I1001 09:47:04.372694 900 server.go:176] "Starting Kubernetes Scheduler" version="v1.36.4+k3s1"1563machine # [ 33.492165] k3s[900]: I1001 09:47:04.372766 900 server.go:178] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1564machine # [ 33.501183] k3s[900]: I1001 09:47:04.386451 900 secure_serving.go:214] Serving securely on 127.0.0.1:102591565machine # [ 33.502659] k3s[900]: I1001 09:47:04.386633 900 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1566machine # [ 33.507852] k3s[900]: I1001 09:47:04.386662 900 shared_informer.go:402] "Waiting for caches to sync"1567machine # [ 33.509376] k3s[900]: I1001 09:47:04.386701 900 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"1568machine # [ 33.516352] k3s[900]: I1001 09:47:04.386859 900 tlsconfig.go:243] "Starting DynamicServingCertificateController"1569machine # [ 33.518713] k3s[900]: I1001 09:47:04.389167 900 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"1570machine # [ 33.524540] k3s[900]: I1001 09:47:04.389192 900 shared_informer.go:402] "Waiting for caches to sync"1571machine # [ 33.527997] k3s[900]: I1001 09:47:04.389212 900 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"1572machine # [ 33.533511] k3s[900]: I1001 09:47:04.389229 900 shared_informer.go:402] "Waiting for caches to sync"1573machine # Error from server (NotFound): namespaces "niks3" not found1574machine # [ 33.601575] k3s[900]: I1001 09:47:04.486939 900 shared_informer.go:409] "Caches are synced"1575machine # [ 33.604280] k3s[900]: I1001 09:47:04.489452 900 shared_informer.go:409] "Caches are synced"1576machine # [ 33.605543] k3s[900]: I1001 09:47:04.489525 900 shared_informer.go:409] "Caches are synced"1577machine # [ 33.637784] k3s[900]: I1001 09:47:04.522567 900 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161578machine # [ 33.644391] k3s[900]: I1001 09:47:04.529731 900 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161579machine # [ 33.735771] k3s[900]: I1001 09:47:04.621016 900 controller.go:667] quota admission added evaluator for: replicasets.apps1580machine # [ 33.769303] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Deleting manifest at \"/var/lib/rancher/k3s/server/manifests/local-storage.yaml\"" object=kube-system/local-storage reason=DeletingManifest type=Normal1581machine # [ 33.786446] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/niks3.yaml\"" object=kube-system/niks3 reason=ApplyingManifest type=Normal1582machine # [ 33.873651] k3s[900]: I1001 09:47:04.758931 900 controller.go:667] quota admission added evaluator for: helmcharts.helm.cattle.io1583machine # [ 33.881605] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/niks3.yaml\"" object=kube-system/niks3 reason=AppliedManifest type=Normal1584machine # [ 33.902843] k3s[900]: time="2026-10-01T09:47:04Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/rolebindings.yaml\"" object=kube-system/rolebindings reason=ApplyingManifest type=Normal1585machine # [ 34.420230] k3s[900]: time="2026-10-01T09:47:05Z" 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=Normal1586machine # [ 34.428347] k3s[900]: I1001 09:47:05.305142 900 shared_informer.go:409] "Caches are synced"1587machine # [ 34.473061] systemd[1]: Created slice libcontainer container kubepods-burstable-pod107789fd_871f_4c80_a7a5_0fc619c3a35b.slice.1588machine # [ 34.487122] k3s[900]: I1001 09:47:05.372480 900 shared_informer.go:409] "Caches are synced"1589machine # [ 34.494055] k3s[900]: I1001 09:47:05.372687 900 garbagecollector.go:166] "Garbage collector: all resource monitors have synced"1590machine # [ 34.498668] k3s[900]: I1001 09:47:05.372706 900 garbagecollector.go:169] "Proceeding to collect garbage"1591machine # [ 34.500877] k3s[900]: I1001 09:47:05.385439 900 controller.go:667] quota admission added evaluator for: jobs.batch1592machine # [ 34.610359] k3s[900]: I1001 09:47:05.494844 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-svbks\" (UniqueName: \"kubernetes.io/projected/107789fd-871f-4c80-a7a5-0fc619c3a35b-kube-api-access-svbks\") pod \"coredns-54996dc9b4-66lkd\" (UID: \"107789fd-871f-4c80-a7a5-0fc619c3a35b\") " pod="kube-system/coredns-54996dc9b4-66lkd"1593machine # [ 34.619163] k3s[900]: I1001 09:47:05.494922 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"config-volume\" (UniqueName: \"kubernetes.io/configmap/107789fd-871f-4c80-a7a5-0fc619c3a35b-config-volume\") pod \"coredns-54996dc9b4-66lkd\" (UID: \"107789fd-871f-4c80-a7a5-0fc619c3a35b\") " pod="kube-system/coredns-54996dc9b4-66lkd"1594machine # [ 34.626796] k3s[900]: I1001 09:47:05.494954 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"custom-config-volume\" (UniqueName: \"kubernetes.io/configmap/107789fd-871f-4c80-a7a5-0fc619c3a35b-custom-config-volume\") pod \"coredns-54996dc9b4-66lkd\" (UID: \"107789fd-871f-4c80-a7a5-0fc619c3a35b\") " pod="kube-system/coredns-54996dc9b4-66lkd"1595machine # Error from server (NotFound): namespaces "niks3" not found1596machine # [ 34.872982] systemd[1]: run-netns-cni\x2deda478f9\x2dc87f\x2d03ef\x2d91d8\x2d050a270381c0.mount: Deactivated successfully.1597machine # [ 34.876545] k3s[900]: E1001 09:47:05.761918 900 remote_runtime.go:237] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"d982f94e268b04eeb59eb3fb675b70ab754539d684ae18850dacb2a917334d79\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory"1598machine # [ 34.882119] k3s[900]: E1001 09:47:05.762047 900 kuberuntime_sandbox.go:70] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"d982f94e268b04eeb59eb3fb675b70ab754539d684ae18850dacb2a917334d79\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-54996dc9b4-66lkd"1599machine # [ 34.896124] k3s[900]: E1001 09:47:05.762076 900 kuberuntime_manager.go:1640] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"d982f94e268b04eeb59eb3fb675b70ab754539d684ae18850dacb2a917334d79\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-54996dc9b4-66lkd"1600machine # [ 34.904197] k3s[900]: E1001 09:47:05.762183 900 pod_workers.go:1338] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"coredns-54996dc9b4-66lkd_kube-system(107789fd-871f-4c80-a7a5-0fc619c3a35b)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"coredns-54996dc9b4-66lkd_kube-system(107789fd-871f-4c80-a7a5-0fc619c3a35b)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"d982f94e268b04eeb59eb3fb675b70ab754539d684ae18850dacb2a917334d79\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/coredns-54996dc9b4-66lkd" podUID="107789fd-871f-4c80-a7a5-0fc619c3a35b"1601machine # [ 34.916432] k3s[900]: time="2026-10-01T09:47:05Z" 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=Normal1602machine # [ 34.924430] k3s[900]: time="2026-10-01T09:47:05Z" 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=Normal1603machine # [ 34.947706] systemd[1]: Created slice libcontainer container kubepods-burstable-pod8207657e_1852_44fc_a942_0000762ad4b9.slice.1604machine # [ 34.950572] k3s[900]: time="2026-10-01T09:47:05Z" level=info msg="Tunnel authorizer set Kubelet Port 0.0.0.0:10250"1605machine # [ 34.955829] k3s[900]: time="2026-10-01T09:47:05Z" 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=Normal1606machine # [ 35.013911] k3s[900]: I1001 09:47:05.899208 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-cache\") pod \"helm-install-niks3-s8pql\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") " pod="kube-system/helm-install-niks3-s8pql"1607machine # [ 35.021533] k3s[900]: I1001 09:47:05.899283 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-tmp\") pod \"helm-install-niks3-s8pql\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") " pod="kube-system/helm-install-niks3-s8pql"1608machine # [ 35.028297] k3s[900]: I1001 09:47:05.899318 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"content\" (UniqueName: \"kubernetes.io/configmap/8207657e-1852-44fc-a942-0000762ad4b9-content\") pod \"helm-install-niks3-s8pql\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") " pod="kube-system/helm-install-niks3-s8pql"1609machine # [ 35.034863] k3s[900]: I1001 09:47:05.899347 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-jh8c5\" (UniqueName: \"kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-kube-api-access-jh8c5\") pod \"helm-install-niks3-s8pql\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") " pod="kube-system/helm-install-niks3-s8pql"1610machine # [ 35.041466] k3s[900]: I1001 09:47:05.899379 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-helm\") pod \"helm-install-niks3-s8pql\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") " pod="kube-system/helm-install-niks3-s8pql"1611machine # [ 35.047423] k3s[900]: I1001 09:47:05.899415 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-config\") pod \"helm-install-niks3-s8pql\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") " pod="kube-system/helm-install-niks3-s8pql"1612machine # [ 35.053092] k3s[900]: I1001 09:47:05.899448 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"values\" (UniqueName: \"kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-values\") pod \"helm-install-niks3-s8pql\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") " pod="kube-system/helm-install-niks3-s8pql"1613machine # [ 35.456128] k3s[900]: time="2026-10-01T09:47:06Z" 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=Normal1614machine # [ 35.644604] k3s[900]: E1001 09:47:06.529302 900 remote_runtime.go:237] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"bca8e8cf6967007828f39c9075ab4a0c3c5b5389fce649e05fe66ce70b937b52\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory"1615machine # [ 35.653578] k3s[900]: E1001 09:47:06.529413 900 kuberuntime_sandbox.go:70] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"bca8e8cf6967007828f39c9075ab4a0c3c5b5389fce649e05fe66ce70b937b52\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-s8pql"1616machine # [ 35.661286] k3s[900]: E1001 09:47:06.529447 900 kuberuntime_manager.go:1640] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"bca8e8cf6967007828f39c9075ab4a0c3c5b5389fce649e05fe66ce70b937b52\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-s8pql"1617machine # [ 35.668872] k3s[900]: E1001 09:47:06.529604 900 pod_workers.go:1338] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"helm-install-niks3-s8pql_kube-system(8207657e-1852-44fc-a942-0000762ad4b9)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"helm-install-niks3-s8pql_kube-system(8207657e-1852-44fc-a942-0000762ad4b9)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"bca8e8cf6967007828f39c9075ab4a0c3c5b5389fce649e05fe66ce70b937b52\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/helm-install-niks3-s8pql" podUID="8207657e-1852-44fc-a942-0000762ad4b9"1618machine # [ 35.679567] k3s[900]: time="2026-10-01T09:47:06Z" 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=Normal1619machine # [ 35.775474] k3s[900]: time="2026-10-01T09:47:06Z" level=info msg="Flannel found PodCIDR assigned for node machine"1620machine # [ 35.778012] k3s[900]: time="2026-10-01T09:47:06Z" level=info msg="The interface eth0 with ipv4 address 10.0.2.15 will be used by flannel"1621machine # [ 35.780630] k3s[900]: I1001 09:47:06.663980 900 kube.go:139] Waiting 10m0s for node controller to sync1622machine # [ 35.782617] k3s[900]: I1001 09:47:06.664090 900 kube.go:537] Starting kube subnet manager1623machine # Error from server (NotFound): namespaces "niks3" not found1624machine # [ 36.780251] k3s[900]: I1001 09:47:07.664793 900 kube.go:163] Node controller sync successful1625machine # [ 36.780478] k3s[900]: I1001 09:47:07.664946 900 vxlan.go:128] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false1626machine # [ 36.784894] k3s[900]: I1001 09:47:07.669231 900 kube.go:704] List of node(machine) annotations: map[string]string{"alpha.kubernetes.io/provided-node-ip":"10.0.2.15,fec0::1133:4ee:3c9c:65cb", "k3s.io/hostname":"machine", "k3s.io/internal-ip":"10.0.2.15,fec0::1133:4ee:3c9c:65cb", "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"}1627machine # [ 36.828898] k3s[900]: I1001 09:47:07.713197 900 iptables.go:50] Starting flannel in iptables mode...1628machine # [ 36.844599] k3s[900]: time="2026-10-01T09:47:07Z" level=warning msg="no subnet found for key: FLANNEL_NETWORK in file: /run/flannel/subnet.env"1629machine # [ 36.848140] k3s[900]: time="2026-10-01T09:47:07Z" level=warning msg="no subnet found for key: FLANNEL_SUBNET in file: /run/flannel/subnet.env"1630machine # [ 36.854372] k3s[900]: time="2026-10-01T09:47:07Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_NETWORK in file: /run/flannel/subnet.env"1631machine # [ 36.857889] k3s[900]: time="2026-10-01T09:47:07Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_SUBNET in file: /run/flannel/subnet.env"1632machine # [ 36.861113] k3s[900]: I1001 09:47:07.713394 900 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 rules1633machine # [ 36.865258] k3s[900]: I1001 09:47:07.717280 900 kube.go:558] Creating the node lease for IPv4. This is the n.Spec.PodCIDRs: [10.42.0.0/24]1634machine # [ 36.910688] (udev-worker)[1338]: Network interface NamePolicy= disabled on kernel command line.1635machine # [ 36.929620] k3s[900]: I1001 09:47:07.814980 900 iptables.go:111] Setting up masking rules1636machine # [ 36.946524] k3s[900]: I1001 09:47:07.831902 900 iptables.go:212] Changing default FORWARD chain policy to ACCEPT1637machine # [ 36.950917] dhcpcd[662]: flannel.1: IAID 61:7b:cd:761638machine # [ 36.952817] dhcpcd[662]: flannel.1: adding address fe80::fcfd:61ff:fe7b:cd761639machine # [ 36.959496] k3s[900]: time="2026-10-01T09:47:07Z" level=info msg="Wrote flannel subnet file to /run/flannel/subnet.env"1640machine # [ 36.961463] k3s[900]: time="2026-10-01T09:47:07Z" level=info msg="Running flannel backend"1641machine # [ 36.962658] k3s[900]: I1001 09:47:07.844914 900 vxlan_network.go:68] watching for new subnet leases1642machine # [ 36.964108] k3s[900]: I1001 09:47:07.844945 900 vxlan_network.go:115] starting vxlan device watcher1643machine # [ 37.030124] k3s[900]: I1001 09:47:07.915379 900 iptables.go:358] bootstrap done1644machine # [ 37.066456] k3s[900]: I1001 09:47:07.951776 900 iptables.go:358] bootstrap done1645machine # Error from server (NotFound): namespaces "niks3" not found1646machine # [ 37.571063] dhcpcd[662]: flannel.1: soliciting a DHCP lease1647machine # [ 38.394801] dhcpcd[662]: flannel.1: soliciting an IPv6 router1648machine # [ 38.407198] k3s[900]: time="2026-10-01T09:47:09Z" level=info msg="Connecting to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1649machine # [ 38.410287] k3s[900]: time="2026-10-01T09:47:09Z" level=info msg="Started tunnel to 10.0.2.15:6443"1650machine # [ 38.412570] k3s[900]: time="2026-10-01T09:47:09Z" level=info msg="Stopped tunnel to 127.0.0.1:6443"1651machine # [ 38.414728] k3s[900]: time="2026-10-01T09:47:09Z" level=info msg="Proxy done" err="context canceled" url="wss://127.0.0.1:6443/v1-k3s/connect"1652machine # [ 38.417814] k3s[900]: time="2026-10-01T09:47:09Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF"1653machine # [ 38.421252] k3s[900]: time="2026-10-01T09:47:09Z" level=info msg="Handling backend connection request [machine]"1654machine # [ 38.423597] k3s[900]: time="2026-10-01T09:47:09Z" level=info msg="Connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1655machine # [ 38.426168] k3s[900]: time="2026-10-01T09:47:09Z" level=info msg="Remotedialer connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect"1656machine # Error from server (NotFound): namespaces "niks3" not found1657machine # [ 38.748854] k3s[900]: I1001 09:47:09.634060 900 kuberuntime_manager.go:2172] "Updating runtime config through cri with podcidr" CIDR="10.42.0.0/24"1658machine # [ 38.752184] k3s[900]: I1001 09:47:09.637498 900 kubelet_network.go:48] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="10.42.0.0/24"1659machine # Error from server (NotFound): namespaces "niks3" not found1660machine # [ 39.925605] k3s[900]: time="2026-10-01T09:47:10Z" level=info msg="Starting network policy controller version v2.6.3-k3s1, built on 1970-01-01T01:01:01Z, go1.26.7"1661machine # [ 39.929099] k3s[900]: I1001 09:47:10.810342 900 network_policy_controller.go:164] Starting network policy controller1662machine # [ 40.110879] k3s[900]: I1001 09:47:10.996235 900 network_policy_controller.go:179] Starting network policy controller full sync goroutine1663machine # Error from server (NotFound): namespaces "niks3" not found1664machine # Error from server (NotFound): namespaces "niks3" not found1665machine # [ 42.571952] dhcpcd[662]: flannel.1: probing for an IPv4LL address1666machine # Error from server (NotFound): namespaces "niks3" not found1667machine # Error from server (NotFound): namespaces "niks3" not found1668machine # Error from server (NotFound): namespaces "niks3" not found1669machine # [ 46.439850] (udev-worker)[1543]: Network interface NamePolicy= disabled on kernel command line.1670machine # [ 46.460997] cni0: port 1(veth7ecb998f) entered blocking state1671machine # [ 46.461034] cni0: port 1(veth7ecb998f) entered disabled state1672machine # [ 46.461068] veth7ecb998f: entered allmulticast mode1673machine # [ 46.461197] veth7ecb998f: entered promiscuous mode1674machine # [ 46.467721] (udev-worker)[1596]: Network interface NamePolicy= disabled on kernel command line.1675machine # [ 46.497515] cni0: port 1(veth7ecb998f) entered blocking state1676machine # [ 46.497553] cni0: port 1(veth7ecb998f) entered forwarding state1677machine # [ 46.527274] dhcpcd[662]: veth7ecb998f: IAID c2:cb:56:3b1678machine # [ 46.528353] dhcpcd[662]: veth7ecb998f: adding address fe80::9c37:c2ff:fecb:563b1679machine # [ 46.585684] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount2462895329.mount: Deactivated successfully.1680machine # [ 46.664628] systemd[1]: Started libcontainer container ad4165e7020d1d98a125d8f524655f6b398274c9e67f4dea900d3017cfdb171b.1681machine # Error from server (NotFound): namespaces "niks3" not found1682machine # [ 47.195678] dhcpcd[662]: flannel.1: using IPv4LL address 169.254.174.1051683machine # [ 47.200384] dhcpcd[662]: flannel.1: adding route to 169.254.0.0/161684machine # [ 47.446836] (udev-worker)[1624]: Network interface NamePolicy= disabled on kernel command line.1685machine # [ 47.452726] cni0: port 2(veth630fde4e) entered blocking state1686machine # [ 47.452762] cni0: port 2(veth630fde4e) entered disabled state1687machine # [ 47.452802] veth630fde4e: entered allmulticast mode1688machine # [ 47.452934] veth630fde4e: entered promiscuous mode1689machine # [ 47.483821] cni0: port 2(veth630fde4e) entered blocking state1690machine # [ 47.483852] cni0: port 2(veth630fde4e) entered forwarding state1691machine # [ 47.533281] dhcpcd[662]: veth630fde4e: waiting for carrier1692machine # [ 47.536313] dhcpcd[662]: veth630fde4e: carrier acquired1693machine # [ 47.544311] dhcpcd[662]: veth630fde4e: IAID 0b:b9:6b:781694machine # [ 47.546451] dhcpcd[662]: veth630fde4e: adding address fe80::cc2c:bff:feb9:6b781695machine # [ 47.653885] systemd[1]: Started libcontainer container db542b2c1bc5ab8ba49b6eeffa16159ef198ad6d499f92c8ec319b1096f68dc4.1696machine # [ 47.704560] systemd[1]: Started libcontainer container 7887e700b3aff1228c0a4c1f0196260cc9e4b2b3fa10fed53a07ee92f2ee9111.1697machine # [ 47.902216] dhcpcd[662]: veth630fde4e: soliciting a DHCP lease1698machine # [ 47.925432] k3s[900]: I1001 09:47:18.810339 900 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/coredns-54996dc9b4-66lkd" podStartSLOduration=13.81031354 podStartE2EDuration="13.81031354s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-10-01 09:47:05 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-10-01 09:47:18.81022168 +0000 UTC m=+26.764827681" watchObservedRunningTime="2026-10-01 09:47:18.81031354 +0000 UTC m=+26.764919541"1699machine # [ 48.164768] dhcpcd[662]: veth7ecb998f: soliciting a DHCP lease1700machine # Error from server (NotFound): namespaces "niks3" not found1701machine # [ 48.410804] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount1206517490.mount: Deactivated successfully.1702machine # [ 48.463735] dhcpcd[662]: veth7ecb998f: soliciting an IPv6 router1703machine # [ 49.439424] dhcpcd[662]: veth630fde4e: soliciting an IPv6 router1704machine # [ 49.453080] systemd[1]: Started libcontainer container 3f36988ac81dd31a1c1b1112fc3b6d39307c714c3a7702ec07528ce287856578.1705machine # [ 49.567017] k3s[900]: I1001 09:47:20.450903 900 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/helm-install-niks3-s8pql" podStartSLOduration=15.45088368 podStartE2EDuration="15.45088368s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-10-01 09:47:05 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-10-01 09:47:20.44820722 +0000 UTC m=+28.402813221" watchObservedRunningTime="2026-10-01 09:47:20.45088368 +0000 UTC m=+28.405489681"1706machine # Error from server (NotFound): namespaces "niks3" not found1707machine # [ 50.397626] dhcpcd[662]: flannel.1: no IPv6 Routers available1708machine # Error from server (NotFound): namespaces "niks3" not found1709machine # [ 51.176183] k3s[900]: I1001 09:47:22.060963 900 alloc.go:329] "allocated clusterIPs" service="niks3/niks3" clusterIPs={"IPv4":"10.43.49.214"}1710machine # [ 51.245545] k3s[900]: I1001 09:47:22.130888 900 controller.go:667] quota admission added evaluator for: cronjobs.batch1711machine # [ 51.302966] systemd[1]: cri-containerd-3f36988ac81dd31a1c1b1112fc3b6d39307c714c3a7702ec07528ce287856578.scope: Deactivated successfully.1712machine # [ 51.306641] systemd[1]: cri-containerd-3f36988ac81dd31a1c1b1112fc3b6d39307c714c3a7702ec07528ce287856578.scope: Consumed 831ms CPU time over 1.849s wall clock time, 37.5M memory peak, 4.5M incoming IP traffic, 95.8K outgoing IP traffic.1713machine # [ 51.396917] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-3f36988ac81dd31a1c1b1112fc3b6d39307c714c3a7702ec07528ce287856578-rootfs.mount: Deactivated successfully.1714machine # [ 51.460574] systemd[1]: Created slice libcontainer container kubepods-besteffort-podfc6b615c_4396_4ad4_987c_41725edee4da.slice.1715machine # [ 51.539595] k3s[900]: I1001 09:47:22.424727 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"db\" (UniqueName: \"kubernetes.io/secret/fc6b615c-4396-4ad4-987c-41725edee4da-db\") pod \"niks3-5b6bd764d7-zm5mx\" (UID: \"fc6b615c-4396-4ad4-987c-41725edee4da\") " pod="niks3/niks3-5b6bd764d7-zm5mx"1716machine # [ 51.544199] k3s[900]: I1001 09:47:22.424780 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"oidc\" (UniqueName: \"kubernetes.io/configmap/fc6b615c-4396-4ad4-987c-41725edee4da-oidc\") pod \"niks3-5b6bd764d7-zm5mx\" (UID: \"fc6b615c-4396-4ad4-987c-41725edee4da\") " pod="niks3/niks3-5b6bd764d7-zm5mx"1717machine # [ 51.550263] k3s[900]: I1001 09:47:22.424807 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/fc6b615c-4396-4ad4-987c-41725edee4da-token\") pod \"niks3-5b6bd764d7-zm5mx\" (UID: \"fc6b615c-4396-4ad4-987c-41725edee4da\") " pod="niks3/niks3-5b6bd764d7-zm5mx"1718machine # [ 51.555231] k3s[900]: I1001 09:47:22.424822 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"s3\" (UniqueName: \"kubernetes.io/secret/fc6b615c-4396-4ad4-987c-41725edee4da-s3\") pod \"niks3-5b6bd764d7-zm5mx\" (UID: \"fc6b615c-4396-4ad4-987c-41725edee4da\") " pod="niks3/niks3-5b6bd764d7-zm5mx"1719machine # [ 51.559501] k3s[900]: I1001 09:47:22.424847 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-x5hdl\" (UniqueName: \"kubernetes.io/projected/fc6b615c-4396-4ad4-987c-41725edee4da-kube-api-access-x5hdl\") pod \"niks3-5b6bd764d7-zm5mx\" (UID: \"fc6b615c-4396-4ad4-987c-41725edee4da\") " pod="niks3/niks3-5b6bd764d7-zm5mx"1720machine # [ 51.859751] cni0: port 3(veth34dade1f) entered blocking state1721machine # [ 51.859791] cni0: port 3(veth34dade1f) entered disabled state1722machine # [ 51.859825] veth34dade1f: entered allmulticast mode1723machine # [ 51.859975] veth34dade1f: entered promiscuous mode1724machine # [ 51.880132] cni0: port 3(veth34dade1f) entered blocking state1725machine # [ 51.880164] cni0: port 3(veth34dade1f) entered forwarding state1726machine # [ 51.937778] (udev-worker)[2103]: Network interface NamePolicy= disabled on kernel command line.1727machine # [ 51.985317] dhcpcd[662]: veth34dade1f: IAID 44:7c:e2:3d1728machine # [ 51.986786] dhcpcd[662]: veth34dade1f: adding address fe80::4091:44ff:fe7c:e23d1729machine # [ 52.024565] systemd[1]: Started libcontainer container bd4d1fd2c75abb78f336c3f7de556082ebb9ff50e2ab707829ca617ef9e1978f.1730machine # [ 52.574672] systemd[1]: cri-containerd-db542b2c1bc5ab8ba49b6eeffa16159ef198ad6d499f92c8ec319b1096f68dc4.scope: Deactivated successfully.1731machine # [ 52.593108] systemd[1]: Started libcontainer container 0cc4530248f784bd2385ad8011e9818d413af025a4a41796684be66006e0d387.1732machine # [ 52.641730] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-db542b2c1bc5ab8ba49b6eeffa16159ef198ad6d499f92c8ec319b1096f68dc4-rootfs.mount: Deactivated successfully.1733machine # [ 52.723614] postgres[2224]: [2224] ERROR: relation "goose_db_version" does not exist at character 361734machine # [ 52.728276] postgres[2224]: [2224] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1735machine # [ 52.782977] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-db542b2c1bc5ab8ba49b6eeffa16159ef198ad6d499f92c8ec319b1096f68dc4-shm.mount: Deactivated successfully.1736machine # [ 52.871804] dhcpcd[662]: veth630fde4e: carrier lost[ 52.874247] cni0: port 2(veth630fde4e) entered disabled state1737machine # [ 52.877555] veth630fde4e (unregistering): left allmulticast mode1738machine # [ 52.877581] veth630fde4e (unregistering): left promiscuous mode1739machine # 1740machine # [ 52.877595] cni0: port 2(veth630fde4e) entered disabled state1741machine # [ 52.915062] systemd[1]: run-netns-cni\x2decdfe3fb\x2d0f56\x2dfece\x2ddf20\x2d591c68790081.mount: Deactivated successfully.1742machine # [ 52.936890] dhcpcd[662]: veth630fde4e: deleting address fe80::cc2c:bff:feb9:6b781743machine # [ 52.962998] k3s[900]: I1001 09:47:23.847862 900 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/niks3-5b6bd764d7-zm5mx" podStartSLOduration=1.8478411000000001 podStartE2EDuration="1.8478411s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-10-01 09:47:22 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-10-01 09:47:23.63079072 +0000 UTC m=+31.585396721" watchObservedRunningTime="2026-10-01 09:47:23.8478411 +0000 UTC m=+31.802447101"1744machine # [ 53.001107] dhcpcd[662]: veth630fde4e: removing interface1745machine # [ 53.062974] k3s[900]: I1001 09:47:23.947705 900 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-values\" (UniqueName: \"kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-values\") pod \"8207657e-1852-44fc-a942-0000762ad4b9\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") "1746machine # [ 53.067902] k3s[900]: I1001 09:47:23.947768 900 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-tmp\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-tmp\") pod \"8207657e-1852-44fc-a942-0000762ad4b9\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") "1747machine # [ 53.072696] k3s[900]: I1001 09:47:23.947793 900 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-kube-api-access-jh8c5\" (UniqueName: \"kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-kube-api-access-jh8c5\") pod \"8207657e-1852-44fc-a942-0000762ad4b9\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") "1748machine # [ 53.077635] k3s[900]: I1001 09:47:23.947827 900 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-cache\") pod \"8207657e-1852-44fc-a942-0000762ad4b9\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") "1749machine # [ 53.082298] k3s[900]: I1001 09:47:23.947850 900 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-config\") pod \"8207657e-1852-44fc-a942-0000762ad4b9\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") "1750machine # [ 53.086989] k3s[900]: I1001 09:47:23.947878 900 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/configmap/8207657e-1852-44fc-a942-0000762ad4b9-content\" (UniqueName: \"kubernetes.io/configmap/8207657e-1852-44fc-a942-0000762ad4b9-content\") pod \"8207657e-1852-44fc-a942-0000762ad4b9\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") "1751machine # [ 53.091664] k3s[900]: I1001 09:47:23.947900 900 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-helm\") pod \"8207657e-1852-44fc-a942-0000762ad4b9\" (UID: \"8207657e-1852-44fc-a942-0000762ad4b9\") "1752machine # [ 53.097016] k3s[900]: I1001 09:47:23.962467 900 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/configmap/8207657e-1852-44fc-a942-0000762ad4b9-content" pod "8207657e-1852-44fc-a942-0000762ad4b9" (UID: "8207657e-1852-44fc-a942-0000762ad4b9"). InnerVolumeSpecName "content". PluginName "kubernetes.io/configmap", VolumeGIDValue ""1753machine # [ 53.107749] k3s[900]: I1001 09:47:23.993026 900 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-kube-api-access-jh8c5" pod "8207657e-1852-44fc-a942-0000762ad4b9" (UID: "8207657e-1852-44fc-a942-0000762ad4b9"). InnerVolumeSpecName "kube-api-access-jh8c5". PluginName "kubernetes.io/projected", VolumeGIDValue ""1754machine # [ 53.112920] k3s[900]: I1001 09:47:23.993024 900 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-helm" pod "8207657e-1852-44fc-a942-0000762ad4b9" (UID: "8207657e-1852-44fc-a942-0000762ad4b9"). InnerVolumeSpecName "klipper-helm". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1755machine # [ 53.117517] k3s[900]: I1001 09:47:23.993603 900 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-config" pod "8207657e-1852-44fc-a942-0000762ad4b9" (UID: "8207657e-1852-44fc-a942-0000762ad4b9"). InnerVolumeSpecName "klipper-config". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1756machine # [ 53.122091] k3s[900]: I1001 09:47:23.995785 900 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-values" pod "8207657e-1852-44fc-a942-0000762ad4b9" (UID: "8207657e-1852-44fc-a942-0000762ad4b9"). InnerVolumeSpecName "values". PluginName "kubernetes.io/projected", VolumeGIDValue ""1757machine # [ 53.126732] k3s[900]: I1001 09:47:24.007645 900 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-tmp" pod "8207657e-1852-44fc-a942-0000762ad4b9" (UID: "8207657e-1852-44fc-a942-0000762ad4b9"). InnerVolumeSpecName "tmp". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1758machine # [ 53.132682] k3s[900]: I1001 09:47:24.018026 900 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-cache" pod "8207657e-1852-44fc-a942-0000762ad4b9" (UID: "8207657e-1852-44fc-a942-0000762ad4b9"). InnerVolumeSpecName "klipper-cache". PluginName "kubernetes.io/empty-dir", VolumeGIDValue ""1759machine # [ 53.163040] k3s[900]: I1001 09:47:24.048381 900 reconciler_common.go:299] "Volume detached for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-tmp\") on node \"machine\" DevicePath \"\""1760machine # [ 53.166378] k3s[900]: I1001 09:47:24.048444 900 reconciler_common.go:299] "Volume detached for volume \"kube-api-access-jh8c5\" (UniqueName: \"kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-kube-api-access-jh8c5\") on node \"machine\" DevicePath \"\""1761machine # [ 53.169637] k3s[900]: I1001 09:47:24.048550 900 reconciler_common.go:299] "Volume detached for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-cache\") on node \"machine\" DevicePath \"\""1762machine # [ 53.172665] k3s[900]: I1001 09:47:24.048562 900 reconciler_common.go:299] "Volume detached for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-config\") on node \"machine\" DevicePath \"\""1763machine # [ 53.175687] k3s[900]: I1001 09:47:24.048573 900 reconciler_common.go:299] "Volume detached for volume \"content\" (UniqueName: \"kubernetes.io/configmap/8207657e-1852-44fc-a942-0000762ad4b9-content\") on node \"machine\" DevicePath \"\""1764machine # [ 53.178908] k3s[900]: I1001 09:47:24.048584 900 reconciler_common.go:299] "Volume detached for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/8207657e-1852-44fc-a942-0000762ad4b9-klipper-helm\") on node \"machine\" DevicePath \"\""1765machine # [ 53.182031] k3s[900]: I1001 09:47:24.048594 900 reconciler_common.go:299] "Volume detached for volume \"values\" (UniqueName: \"kubernetes.io/projected/8207657e-1852-44fc-a942-0000762ad4b9-values\") on node \"machine\" DevicePath \"\""1766machine # [ 53.185051] dhcpcd[662]: veth7ecb998f: probing for an IPv4LL address1767machine # [ 53.397924] systemd[1]: var-lib-kubelet-pods-8207657e\x2d1852\x2d44fc\x2da942\x2d0000762ad4b9-volumes-kubernetes.io\x7eprojected-values.mount: Deactivated successfully.1768machine # [ 53.402828] systemd[1]: var-lib-kubelet-pods-8207657e\x2d1852\x2d44fc\x2da942\x2d0000762ad4b9-volumes-kubernetes.io\x7eprojected-kube\x2dapi\x2daccess\x2djh8c5.mount: Deactivated successfully.1769machine # [ 53.406648] systemd[1]: var-lib-kubelet-pods-8207657e\x2d1852\x2d44fc\x2da942\x2d0000762ad4b9-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dconfig.mount: Deactivated successfully.1770machine # [ 53.410162] systemd[1]: var-lib-kubelet-pods-8207657e\x2d1852\x2d44fc\x2da942\x2d0000762ad4b9-volumes-kubernetes.io\x7eempty\x2ddir-tmp.mount: Deactivated successfully.1771machine # [ 53.413330] systemd[1]: var-lib-kubelet-pods-8207657e\x2d1852\x2d44fc\x2da942\x2d0000762ad4b9-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dcache.mount: Deactivated successfully.1772machine # [ 53.416683] systemd[1]: var-lib-kubelet-pods-8207657e\x2d1852\x2d44fc\x2da942\x2d0000762ad4b9-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dhelm.mount: Deactivated successfully.1773machine # [ 53.564331] k3s[900]: I1001 09:47:24.449633 900 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="db542b2c1bc5ab8ba49b6eeffa16159ef198ad6d499f92c8ec319b1096f68dc4"1774machine # [ 53.577949] systemd[1]: Removed slice libcontainer container kubepods-burstable-pod8207657e_1852_44fc_a942_0000762ad4b9.slice.1775machine # [ 53.581051] systemd[1]: kubepods-burstable-pod8207657e_1852_44fc_a942_0000762ad4b9.slice: Consumed 860ms CPU time over 18.630s wall clock time, 37.9M memory peak, 4.5M incoming IP traffic, 95.8K outgoing IP traffic.1776machine # [ 53.591914] dhcpcd[662]: veth34dade1f: soliciting an IPv6 router1777machine # [ 53.924636] dhcpcd[662]: veth34dade1f: soliciting a DHCP lease1778machine: (finished: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s, in 28.68 seconds)1779machine: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true1780machine: (finished: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true, in 0.20 seconds)1781machine: waiting for success: curl -sf http://localhost:30051/readyz | grep OK1782machine: (finished: waiting for success: curl -sf http://localhost:30051/readyz | grep OK, in 0.04 seconds)1783(finished: subtest: chart deploys and becomes ready, in 28.93 seconds)1784machine: waiting for success: kubectl -n ci get sa builder1785machine: (finished: waiting for success: kubectl -n ci get sa builder, in 0.17 seconds)1786machine: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt1787machine: (finished: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt, in 0.17 seconds)1788machine: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt1789machine # [ 58.389796] dhcpcd[662]: veth7ecb998f: using IPv4LL address 169.254.240.491790machine # [ 58.391826] dhcpcd[662]: veth7ecb998f: adding route to 169.254.0.0/161791machine: (finished: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt, in 0.16 seconds)1792machine: must succeed: readlink -f /run/current-system/sw/bin/niks31793machine: (finished: must succeed: readlink -f /run/current-system/sw/bin/niks3, in 0.02 seconds)1794subtest: allowed service account can push via workload identity1795machine: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/g7phak0a4pn3ngv3id2qqx5cp4iq7r7s-niks3-1.13.0 2>&11796machine # [ 58.925185] dhcpcd[662]: veth34dade1f: probing for an IPv4LL address1797machine: (finished: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/g7phak0a4pn3ngv3id2qqx5cp4iq7r7s-niks3-1.13.0 2>&1, in 1.08 seconds)1798machine: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/g7phak0a4pn3ngv3id2qqx5cp4iq7r7s.narinfo1799machine: (finished: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/g7phak0a4pn3ngv3id2qqx5cp4iq7r7s.narinfo, in 0.02 seconds)1800(finished: subtest: allowed service account can push via workload identity, in 1.10 seconds)1801subtest: write scope does not grant admin1802machine: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status1803machine: (finished: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status, in 0.03 seconds)1804(finished: subtest: write scope does not grant admin, in 0.03 seconds)1805subtest: other service accounts are rejected1806machine: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/g7phak0a4pn3ngv3id2qqx5cp4iq7r7s-niks3-1.13.0 2>&11807machine: (finished: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/g7phak0a4pn3ngv3id2qqx5cp4iq7r7s-niks3-1.13.0 2>&1, in 0.12 seconds)1808(finished: subtest: other service accounts are rejected, in 0.12 seconds)1809subtest: gc cronjob runs against the service1810machine: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual1811machine: (finished: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual, in 0.17 seconds)1812machine: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s1813machine # [ 59.882259] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod3521bb6f_5b22_488c_b243_058f81dbc591.slice.1814machine # [ 60.006633] k3s[900]: I1001 09:47:30.891562 900 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/3521bb6f-5b22-488c-b243-058f81dbc591-token\") pod \"gc-manual-bqcpw\" (UID: \"3521bb6f-5b22-488c-b243-058f81dbc591\") " pod="niks3/gc-manual-bqcpw"1815machine # [ 60.255391] cni0: port 2(veth3d67b681) entered blocking state1816machine # [ 60.255438] cni0: port 2(veth3d67b681) entered disabled state1817machine # [ 60.255476] veth3d67b681: entered allmulticast mode1818machine # [ 60.255613] veth3d67b681: entered promiscuous mode1819machine # [ 60.272333] cni0: port 2(veth3d67b681) entered blocking state1820machine # [ 60.272370] cni0: port 2(veth3d67b681) entered forwarding state1821machine # [ 60.331583] (udev-worker)[2615]: Network interface NamePolicy= disabled on kernel command line.1822machine # [ 60.378818] dhcpcd[662]: veth3d67b681: IAID 2e:77:95:711823machine # [ 60.379760] dhcpcd[662]: veth3d67b681: adding address fe80::3c61:2eff:fe77:95711824machine # [ 60.404687] systemd[1]: Started libcontainer container 1209071684d26eef2bcf6e047bfceee87e5aaa49b4ef0e4eee0994301565a1f0.1825machine # [ 60.466684] dhcpcd[662]: veth7ecb998f: no IPv6 Routers available1826machine # [ 60.533296] systemd[1]: Started libcontainer container d14454b1b7c044d2151fdf3907cb225cb1a50431e244706053bc3d7001207dcd.1827machine # [ 60.544924] dhcpcd[662]: veth3d67b681: soliciting a DHCP lease1828machine # [ 60.612819] k3s[900]: I1001 09:47:31.497827 900 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/gc-manual-bqcpw" podStartSLOduration=1.49780628 podStartE2EDuration="1.49780628s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-10-01 09:47:30 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-10-01 09:47:31.49659692 +0000 UTC m=+39.451202921" watchObservedRunningTime="2026-10-01 09:47:31.49780628 +0000 UTC m=+39.452412281"1829machine # [ 62.022383] dhcpcd[662]: veth3d67b681: soliciting an IPv6 router1830machine # [ 62.609118] systemd[1]: cri-containerd-d14454b1b7c044d2151fdf3907cb225cb1a50431e244706053bc3d7001207dcd.scope: Deactivated successfully.1831machine # [ 62.612951] systemd[1]: cri-containerd-d14454b1b7c044d2151fdf3907cb225cb1a50431e244706053bc3d7001207dcd.scope: Consumed 34ms CPU time over 2.075s wall clock time, 3.8M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic.1832machine # [ 62.664623] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-d14454b1b7c044d2151fdf3907cb225cb1a50431e244706053bc3d7001207dcd-rootfs.mount: Deactivated successfully.1833machine # [ 64.629548] systemd[1]: cri-containerd-1209071684d26eef2bcf6e047bfceee87e5aaa49b4ef0e4eee0994301565a1f0.scope: Deactivated successfully.1834machine # [ 64.650892] dhcpcd[662]: veth34dade1f: using IPv4LL address 169.254.6.1801835machine # [ 64.653049] dhcpcd[662]: veth34dade1f: adding route to 169.254.0.0/161836machine # [ 64.685273] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-1209071684d26eef2bcf6e047bfceee87e5aaa49b4ef0e4eee0994301565a1f0-rootfs.mount: Deactivated successfully.1837machine # [ 64.723944] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-1209071684d26eef2bcf6e047bfceee87e5aaa49b4ef0e4eee0994301565a1f0-shm.mount: Deactivated successfully.1838machine # [ 64.767609] dhcpcd[662]: veth3d67b681: carrier lost[ 64.769854] cni0: port 2(veth3d67b681) entered disabled state1839machine # 1840machine # [ 64.773762] veth3d67b681 (unregistering): left allmulticast mode1841machine # [ 64.773790] veth3d67b681 (unregistering): left promiscuous mode1842machine # [ 64.773806] cni0: port 2(veth3d67b681) entered disabled state1843machine # [ 64.805824] systemd[1]: run-netns-cni\x2d3f1e9ebd\x2d3471\x2df100\x2da42a\x2d836f5d272cde.mount: Deactivated successfully.1844machine # [ 64.808417] dhcpcd[662]: veth3d67b681: deleting address fe80::3c61:2eff:fe77:95711845machine # [ 64.868382] dhcpcd[662]: veth3d67b681: removing interface1846machine # [ 64.943461] k3s[900]: I1001 09:47:35.827916 900 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/secret/3521bb6f-5b22-488c-b243-058f81dbc591-token\" (UniqueName: \"kubernetes.io/secret/3521bb6f-5b22-488c-b243-058f81dbc591-token\") pod \"3521bb6f-5b22-488c-b243-058f81dbc591\" (UID: \"3521bb6f-5b22-488c-b243-058f81dbc591\") "1847machine # [ 64.952304] systemd[1]: var-lib-kubelet-pods-3521bb6f\x2d5b22\x2d488c\x2db243\x2d058f81dbc591-volumes-kubernetes.io\x7esecret-token.mount: Deactivated successfully.1848machine # [ 64.955183] k3s[900]: I1001 09:47:35.840001 900 operation_generator.go:782] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/3521bb6f-5b22-488c-b243-058f81dbc591-token" pod "3521bb6f-5b22-488c-b243-058f81dbc591" (UID: "3521bb6f-5b22-488c-b243-058f81dbc591"). InnerVolumeSpecName "token". PluginName "kubernetes.io/secret", VolumeGIDValue ""1849machine # [ 65.043172] k3s[900]: I1001 09:47:35.928478 900 reconciler_common.go:299] "Volume detached for volume \"token\" (UniqueName: \"kubernetes.io/secret/3521bb6f-5b22-488c-b243-058f81dbc591-token\") on node \"machine\" DevicePath \"\""1850machine # [ 65.596397] dhcpcd[662]: veth34dade1f: no IPv6 Routers available1851machine # [ 65.605335] k3s[900]: I1001 09:47:36.490595 900 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="1209071684d26eef2bcf6e047bfceee87e5aaa49b4ef0e4eee0994301565a1f0"1852machine # [ 65.619771] systemd[1]: Removed slice libcontainer container kubepods-besteffort-pod3521bb6f_5b22_488c_b243_058f81dbc591.slice.1853machine # [ 65.624588] systemd[1]: kubepods-besteffort-pod3521bb6f_5b22_488c_b243_058f81dbc591.slice: Consumed 61ms CPU time over 5.737s wall clock time, 4.3M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic.1854machine: (finished: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s, in 5.82 seconds)1855(finished: subtest: gc cronjob runs against the service, in 5.99 seconds)1856subtest: helm test hook passes1857machine: must succeed: helm test -n niks3 niks3 --timeout 2m >&21858machine # [ 66.668358] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod2e3b5c05_ca49_41d9_9ca1_8b9eee9877bc.slice.1859machine # [ 66.724962] (udev-worker)[2833]: Network interface NamePolicy= disabled on kernel command line.1860machine # [ 66.727194] cni0: port 2(veth5f22ffe5) entered blocking state1861machine # [ 66.727223] cni0: port 2(veth5f22ffe5) entered disabled state1862machine # [ 66.727260] veth5f22ffe5: entered allmulticast mode1863machine # [ 66.727367] veth5f22ffe5: entered promiscuous mode1864machine # [ 66.756516] cni0: port 2(veth5f22ffe5) entered blocking state1865machine # [ 66.756541] cni0: port 2(veth5f22ffe5) entered forwarding state1866machine # [ 66.795602] dhcpcd[662]: veth5f22ffe5: waiting for carrier1867machine # [ 66.796597] dhcpcd[662]: veth5f22ffe5: carrier acquired1868machine # [ 66.804195] dhcpcd[662]: veth5f22ffe5: IAID 4e:93:58:2d1869machine # [ 66.805297] dhcpcd[662]: veth5f22ffe5: adding address fe80::d458:4eff:fe93:582d1870machine # [ 66.888382] systemd[1]: Started libcontainer container b4f9f364b663f7fb9fc0592267626b7979a0e673ee99ae9090f85574784c67c8.1871machine # [ 66.941513] dhcpcd[662]: veth5f22ffe5: soliciting a DHCP lease1872machine # [ 67.016776] systemd[1]: Started libcontainer container c26178ddce9c0d5929135b4f99676bdadeb3ec5fa4c2319de04a5b45673330df.1873machine # [ 67.074773] systemd[1]: cri-containerd-c26178ddce9c0d5929135b4f99676bdadeb3ec5fa4c2319de04a5b45673330df.scope: Deactivated successfully.1874machine # [ 67.077615] systemd[1]: cri-containerd-c26178ddce9c0d5929135b4f99676bdadeb3ec5fa4c2319de04a5b45673330df.scope: Consumed 26ms CPU time over 57ms wall clock time, 4.1M memory peak, 693B incoming IP traffic, 495B outgoing IP traffic.1875machine # [ 67.120861] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-c26178ddce9c0d5929135b4f99676bdadeb3ec5fa4c2319de04a5b45673330df-rootfs.mount: Deactivated successfully.1876machine # [ 68.640146] systemd[1]: cri-containerd-b4f9f364b663f7fb9fc0592267626b7979a0e673ee99ae9090f85574784c67c8.scope: Deactivated successfully.1877machine # [ 68.690219] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-b4f9f364b663f7fb9fc0592267626b7979a0e673ee99ae9090f85574784c67c8-rootfs.mount: Deactivated successfully.1878machine # [ 68.727320] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-b4f9f364b663f7fb9fc0592267626b7979a0e673ee99ae9090f85574784c67c8-shm.mount: Deactivated successfully.1879machine # [ 68.772001] dhcpcd[662]: veth5f22ffe5: carrier lost[ 68.773917] cni0: port 2(veth5f22ffe5) entered disabled state1880machine # [ 68.775033] veth5f22ffe5 (unregistering): left allmulticast mode1881machine # 1882machine # [ 68.775057] veth5f22ffe5 (unregistering): left promiscuous mode1883machine # [ 68.775069] cni0: port 2(veth5f22ffe5) entered disabled state1884machine # [ 68.805383] systemd[1]: run-netns-cni\x2d1a4bf922\x2dd170\x2dfd0c\x2dfb7a\x2d6b519b0a120f.mount: Deactivated successfully.1885machine # [ 68.823077] dhcpcd[662]: veth5f22ffe5: deleting address fe80::d458:4eff:fe93:582d1886machine # NAME: niks31887machine # LAST DEPLOYED: Thu Oct 1 09:47:21 20261888machine # NAMESPACE: niks31889machine # STATUS: deployed1890machine # REVISION: 11891machine # DESCRIPTION: Install complete1892machine # TEST SUITE: niks3-test1893machine # Last Started: Thu Oct 1 09:47:37 20261894machine # Last Completed: Thu Oct 1 09:47:39 20261895machine # Phase: Succeeded1896machine # [ 68.883832] dhcpcd[662]: veth5f22ffe5: removing interface1897machine: (finished: must succeed: helm test -n niks3 niks3 --timeout 2m >&2, in 3.22 seconds)1898(finished: subtest: helm test hook passes, in 3.22 seconds)1899(finished: run the VM test script, in 69.92 seconds)1900test script finished in 69.96s1901cleanup1902kill QemuMachine (pid 45)1903machine # qemu-system-aarch64: terminating on signal 15 from pid 39 (/nix/store/3fl7bdkdxk2k4nssy1d1161isbzn6bsr-python3-3.14.7/bin/python3.14)1904machine # [2026-10-01T09:47:39Z INFO virtiofsd] Client disconnected, shutting down1905machine # [2026-10-01T09:47:39Z INFO virtiofsd] Client disconnected, shutting down1906machine # [2026-10-01T09:47:39Z INFO virtiofsd] Client disconnected, shutting down1907(finished: cleanup, in 0.89 seconds)1908additionally exposed symbols:1909 machine,1910 vlan1,1911 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_ssh1912time=2026-10-01T09:47:29.489Z level=INFO msg="Uploading 8 paths to localhost (0 already cached)"1913time=2026-10-01T09:47:29.489Z level=INFO msg="Uploading g7phak0a4pn3ngv3id2qqx5cp4iq7r7s-niks3-1.13.0 (7.2MB)"1914time=2026-10-01T09:47:29.489Z level=INFO msg="Uploading h0hd048jzxs7fx9a6g75jwrrhbg50bp8-libunistring-1.4.2 (2.0MB)"1915time=2026-10-01T09:47:29.489Z level=INFO msg="Uploading na3qajp3ja0w9yxcsqck86phm9ddhwx2-iana-etc-20251215 (557.8KB)"1916time=2026-10-01T09:47:29.490Z level=INFO msg="Uploading 0s40b0an0cz4vypbji92cb7qbr65icl4-libidn2-2.3.8 (366.1KB)"1917time=2026-10-01T09:47:29.491Z level=INFO msg="Uploading waax852balprvsvdziyaf1h7r3ldvakg-xgcc-15.3.0-libgcc (150.1KB)"1918time=2026-10-01T09:47:29.492Z level=INFO msg="Uploading n7aaryickpnkwwmmkg7xgnlihmmsh55w-mailcap-2.1.54 (116.6KB)"1919time=2026-10-01T09:47:29.493Z level=INFO msg="Uploading m54cs0m994hc3n9lax7sg98sgy729qsa-glibc-2.42-84 (44.4MB)"1920time=2026-10-01T09:47:29.495Z level=INFO msg="Uploading i8an849ir6g3f4n2wrsm88s2qgrzjayq-tzdata-2026c (2.0MB)"1921time=2026-10-01T09:47:30.336Z level=INFO msg="Uploading 8 narinfos"1922time=2026-10-01T09:47:30.376Z level=INFO msg="Upload complete. (973ms)"1923