tribuchet: building on jamie Machine state will be reset. To keep it, pass --keep-machine-state start all VLans (finished: start all VLans, in 0.00 seconds) Test will time out and terminate in 3600.0 seconds run the VM test script machine: waiting for unit k3s.service machine: waiting for the VM to finish booting machine: starting vm machine: QEMU running (pid 45) machine # Disk image does not exist, creating the virtualisation disk image... machine # Formatting '/build/vm-state-machine/tmp.YFR00T96mb', fmt=raw size=8589934592 machine # mke2fs 1.47.4 (6-Mar-2025) machine # Discarding device blocks: 0/2097152 done machine # Creating filesystem with 2097152 4k blocks and 524288 inodes machine # Filesystem UUID: 7dcebace-693b-40e4-9567-e02b02c81a92 machine # Superblock backups stored on blocks: machine # 32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632 machine # machine # Allocating group tables: 0/64 done machine # Writing inode tables: 0/64 done machine # Creating journal (16384 blocks): done machine # Writing superblocks and filesystem accounting information: 0/64 done machine # machine # Virtualisation disk image created. machine # SeaBIOS (version rel-1.17.0-0-gb52ca86e094d-prebuilt.qemu.org) machine # machine # machine # iPXE (http://ipxe.org) 00:02.0 CA00 PCI2.10 PnP PMM+7EFCC730+7EF2C730 CA00 machine # Press Ctrl-B to configure iPXE (PCI 00:02.0)... machine # machine # machine # machine # machine # iPXE (http://ipxe.org) 00:08.0 CB00 PCI2.10 PnP PMM 7EFCC730 7EF2C730 CB00 machine # Press Ctrl-B to configure iPXE (PCI 00:08.0)... machine # machine # machine # Booting from ROM... machine # Probing EDD (edd=off to disable)... o[ 0.000000] Linux version 6.18.49 (nixbld@localhost) (gcc (GCC) 15.3.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT_DYNAMIC Wed Sep 2 12:31:51 UTC 2026 machine # [ 0.000000] Command line: console=ttyS0 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/2j5h69yyypr6ipr8f13644brlzqaxd9q-nixos-system-machine-test/init regInfo=/nix/store/yil5kla6ml0bzhfrmwav86giy6vskrgd-closure-info/registration console=ttyS0,115200n8 console=tty0 machine # [ 0.000000] BIOS-provided physical RAM map: machine # [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable machine # [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007ffd7fff] usable machine # [ 0.000000] BIOS-e820: [mem 0x000000007ffd8000-0x000000007fffffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x00000000b0000000-0x00000000bfffffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000013fffffff] usable machine # [ 0.000000] BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved machine # [ 0.000000] NX (Execute Disable) protection: active machine # [ 0.000000] APIC: Static calls initialized machine # [ 0.000000] SMBIOS 2.8 present. machine # [ 0.000000] DMI: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.17.0-0-gb52ca86e094d-prebuilt.qemu.org 04/01/2014 machine # [ 0.000000] DMI: Memory slots populated: 1/1 machine # [ 0.000000] Hypervisor detected: KVM machine # [ 0.000000] last_pfn = 0x7ffd8 max_arch_pfn = 0x10000000000 machine # [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 machine # [ 0.000000] kvm-clock: using sched offset of 478398190 cycles machine # [ 0.000002] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns machine # [ 0.000004] tsc: Detected 2400.012 MHz processor machine # [ 0.000812] last_pfn = 0x140000 max_arch_pfn = 0x10000000000 machine # [ 0.000838] MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs machine # [ 0.000840] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT machine # [ 0.000877] last_pfn = 0x7ffd8 max_arch_pfn = 0x10000000000 machine # [ 0.002740] found SMP MP-table at [mem 0x000f5450-0x000f545f] machine # [ 0.002750] Using GB pages for direct mapping machine # [ 0.002875] RAMDISK: [mem 0x7e36a000-0x7ffcffff] machine # [ 0.002881] ACPI: Early table checksum verification disabled machine # [ 0.002883] ACPI: RSDP 0x00000000000F5250 000014 (v00 BOCHS ) machine # [ 0.002887] ACPI: RSDT 0x000000007FFE247D 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.002891] ACPI: FACP 0x000000007FFE226D 0000F4 (v03 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.002897] ACPI: DSDT 0x000000007FFE0040 00222D (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.002899] ACPI: FACS 0x000000007FFE0000 000040 machine # [ 0.002900] ACPI: APIC 0x000000007FFE2361 000080 (v03 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.002902] ACPI: HPET 0x000000007FFE23E1 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.002903] ACPI: MCFG 0x000000007FFE2419 00003C (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.002905] ACPI: WAET 0x000000007FFE2455 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.002906] ACPI: Reserving FACP table memory at [mem 0x7ffe226d-0x7ffe2360] machine # [ 0.002907] ACPI: Reserving DSDT table memory at [mem 0x7ffe0040-0x7ffe226c] machine # [ 0.002908] ACPI: Reserving FACS table memory at [mem 0x7ffe0000-0x7ffe003f] machine # [ 0.002908] ACPI: Reserving APIC table memory at [mem 0x7ffe2361-0x7ffe23e0] machine # [ 0.002909] ACPI: Reserving HPET table memory at [mem 0x7ffe23e1-0x7ffe2418] machine # [ 0.002909] ACPI: Reserving MCFG table memory at [mem 0x7ffe2419-0x7ffe2454] machine # [ 0.002910] ACPI: Reserving WAET table memory at [mem 0x7ffe2455-0x7ffe247c] machine # [ 0.003124] No NUMA configuration found machine # [ 0.003125] Faking a node at [mem 0x0000000000000000-0x000000013fffffff] machine # [ 0.003127] NODE_DATA(0) allocated [mem 0x13fff8780-0x13fffdcff] machine # [ 0.005207] Zone ranges: machine # [ 0.005208] DMA [mem 0x0000000000001000-0x0000000000ffffff] machine # [ 0.005209] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] machine # [ 0.005210] Normal [mem 0x0000000100000000-0x000000013fffffff] machine # [ 0.005211] Device empty machine # [ 0.005212] Movable zone start for each node machine # [ 0.005213] Early memory node ranges machine # [ 0.005213] node 0: [mem 0x0000000000001000-0x000000000009efff] machine # [ 0.005214] node 0: [mem 0x0000000000100000-0x000000007ffd7fff] machine # [ 0.005215] node 0: [mem 0x0000000100000000-0x000000013fffffff] machine # [ 0.005216] Initmem setup node 0 [mem 0x0000000000001000-0x000000013fffffff] machine # [ 0.005233] On node 0, zone DMA: 1 pages in unavailable ranges machine # [ 0.005482] On node 0, zone DMA: 97 pages in unavailable ranges machine # [ 0.054909] On node 0, zone Normal: 40 pages in unavailable ranges machine # [ 0.055360] ACPI: PM-Timer IO Port: 0x608 machine # [ 0.055373] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) machine # [ 0.055398] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 machine # [ 0.055400] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) machine # [ 0.055402] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) machine # [ 0.055403] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) machine # [ 0.055404] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) machine # [ 0.055405] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) machine # [ 0.055408] ACPI: Using ACPI (MADT) for SMP configuration information machine # [ 0.055409] ACPI: HPET id: 0x8086a201 base: 0xfed00000 machine # [ 0.055413] TSC deadline timer available machine # [ 0.055417] CPU topo: Max. logical packages: 1 machine # [ 0.055418] CPU topo: Max. logical dies: 1 machine # [ 0.055418] CPU topo: Max. dies per package: 1 machine # [ 0.055421] CPU topo: Max. threads per core: 1 machine # [ 0.055422] CPU topo: Num. cores per package: 2 machine # [ 0.055423] CPU topo: Num. threads per package: 2 machine # [ 0.055423] CPU topo: Allowing 2 present CPUs plus 0 hotplug CPUs machine # [ 0.055444] kvm-guest: APIC: eoi() replaced with kvm_guest_apic_eoi_write() machine # [ 0.055459] kvm-guest: KVM setup pv remote TLB flush machine # [ 0.055462] kvm-guest: setup PV sched yield machine # [ 0.055471] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff] machine # [ 0.055472] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x000fffff] machine # [ 0.055473] PM: hibernation: Registered nosave memory: [mem 0x7ffd8000-0xffffffff] machine # [ 0.055475] [mem 0xc0000000-0xfed1bfff] available for PCI devices machine # [ 0.055476] Booting paravirtualized kernel on KVM machine # [ 0.055480] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns machine # [ 0.059985] setup_percpu: NR_CPUS:384 nr_cpumask_bits:2 nr_cpu_ids:2 nr_node_ids:1 machine # [ 0.062015] percpu: Embedded 98 pages/cpu s278528 r8192 d114688 u1048576 machine # [ 0.062061] kvm-guest: PV spinlocks enabled machine # [ 0.062062] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) machine # [ 0.062065] Kernel command line: console=ttyS0 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/2j5h69yyypr6ipr8f13644brlzqaxd9q-nixos-system-machine-test/init regInfo=/nix/store/yil5kla6ml0bzhfrmwav86giy6vskrgd-closure-info/registration console=ttyS0,115200n8 console=tty0 machine # [ 0.062161] Unknown kernel command line parameters "regInfo=/nix/store/yil5kla6ml0bzhfrmwav86giy6vskrgd-closure-info/registration", will be passed to user space. machine # [ 0.062174] random: crng init done machine # [ 0.062175] printk: log buffer data + meta data: 262144 + 917504 = 1179648 bytes machine # [ 0.066266] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear) machine # [ 0.068241] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear) machine # [ 0.068285] software IO TLB: area num 2. machine # [ 0.135311] Fallback order for Node 0: 0 machine # [ 0.135318] Built 1 zonelists, mobility grouping on. Total pages: 786294 machine # [ 0.135320] Policy zone: Normal machine # [ 0.137733] mem auto-init: stack:all(zero), heap alloc:on, heap free:off machine # [ 0.142918] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1 machine # [ 0.149003] allocated 6291456 bytes of page_ext machine # [ 0.158810] ftrace: allocating 48732 entries in 192 pages machine # [ 0.158812] ftrace: allocated 192 pages with 2 groups machine # [ 0.159662] Dynamic Preempt: lazy machine # [ 0.159849] rcu: Preemptible hierarchical RCU implementation. machine # [ 0.159850] rcu: RCU event tracing is enabled. machine # [ 0.159851] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=2. machine # [ 0.159852] Trampoline variant of Tasks RCU enabled. machine # [ 0.159853] Rude variant of Tasks RCU enabled. machine # [ 0.159853] Tracing variant of Tasks RCU enabled. machine # [ 0.159854] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. machine # [ 0.159854] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2 machine # [ 0.159866] RCU Tasks: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2. machine # [ 0.159868] RCU Tasks Rude: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2. machine # [ 0.159869] RCU Tasks Trace: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2. machine # [ 0.164169] NR_IRQS: 24832, nr_irqs: 440, preallocated irqs: 16 machine # [ 0.164439] rcu: srcu_init: Setting srcu_struct sizes based on contention. machine # [ 0.164446] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns machine # [ 0.164556] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____) machine # [ 0.168053] Console: colour VGA+ 80x25 machine # [ 0.168056] printk: legacy console [tty0] enabled machine # [ 0.199092] printk: legacy console [ttyS0] enabled machine # [ 0.310734] ACPI: Core revision 20250807 machine # [ 0.311618] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns machine # [ 0.313183] APIC: Switch to symmetric I/O mode setup machine # [ 0.314206] x2apic enabled machine # [ 0.314961] APIC: Switched APIC routing to: physical x2apic machine # [ 0.315850] kvm-guest: APIC: send_IPI_mask() replaced with kvm_send_ipi_mask() machine # [ 0.317032] kvm-guest: APIC: send_IPI_mask_allbutself() replaced with kvm_send_ipi_mask_allbutself() machine # [ 0.318559] kvm-guest: setup PV IPIs machine # [ 0.320124] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 machine # [ 0.321135] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229842dd0bd, max_idle_ns: 440795319571 ns machine # [ 0.325412] Calibrating delay loop (skipped) preset value.. 4800.02 BogoMIPS (lpj=2400012) machine # [ 0.326494] x86/cpu: User Mode Instruction Prevention (UMIP) activated machine # [ 0.327559] Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127 machine # [ 0.329156] Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0 machine # [ 0.330413] mitigations: Enabled attack vectors: user_kernel, user_user, guest_host, guest_guest, SMT mitigations: auto machine # [ 0.331410] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl machine # [ 0.333410] Transient Scheduler Attacks: Vulnerable: No microcode machine # [ 0.334409] Spectre V2 : Mitigation: Enhanced / Automatic IBRS machine # [ 0.335410] Speculative Return Stack Overflow: Mitigation: Safe RET machine # [ 0.336410] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization machine # [ 0.337416] Spectre V2 : Enabling IBPB for BPF machine # [ 0.338976] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier machine # [ 0.339411] active return thunk: srso_alias_return_thunk machine # [ 0.340412] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' machine # [ 0.341410] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' machine # [ 0.342409] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' machine # [ 0.343410] x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask' machine # [ 0.344409] x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256' machine # [ 0.345410] x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256' machine # [ 0.346409] x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers' machine # [ 0.348410] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 machine # [ 0.349409] x86/fpu: xstate_offset[5]: 832, xstate_sizes[5]: 64 machine # [ 0.350409] x86/fpu: xstate_offset[6]: 896, xstate_sizes[6]: 512 machine # [ 0.351409] x86/fpu: xstate_offset[7]: 1408, xstate_sizes[7]: 1024 machine # [ 0.352410] x86/fpu: xstate_offset[9]: 2432, xstate_sizes[9]: 8 machine # [ 0.353410] x86/fpu: Enabled xstate features 0x2e7, context size is 2440 bytes, using 'compacted' format. machine # [ 0.383080] Freeing SMP alternatives memory: 44K machine # [ 0.383412] pid_max: default: 32768 minimum: 301 machine # [ 0.384501] LSM: initializing lsm=capability,landlock,yama,bpf,ima machine # [ 0.385508] landlock: Up and running. machine # [ 0.386410] Yama: becoming mindful. machine # [ 0.387517] LSM support for eBPF active machine # [ 0.388338] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear) machine # [ 0.389474] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear) machine # [ 0.392045] smpboot: CPU0: AMD EPYC 9654 96-Core Processor (family: 0x19, model: 0x11, stepping: 0x1) machine # [ 0.392935] Performance Events: Fam17h+ core perfctr, AMD PMU driver. machine # [ 0.393415] ... version: 2 machine # [ 0.394126] ... bit width: 48 machine # [ 0.394412] ... generic counters: 6 machine # [ 0.395174] ... generic bitmap: 000000000000003f machine # [ 0.395423] ... fixed-purpose counters: 0 machine # [ 0.396153] ... fixed-purpose bitmap: 0000000000000000 machine # [ 0.396412] ... value mask: 0000ffffffffffff machine # [ 0.397374] ... max period: 00007fffffffffff machine # [ 0.398144] ... global_ctrl mask: 000000000000003f machine # [ 0.398532] signal: max sigframe size: 3376 machine # [ 0.399372] rcu: Hierarchical SRCU implementation. machine # [ 0.400052] rcu: Max phase no-delay instances is 400. machine # [ 0.400586] Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level machine # [ 0.405872] smp: Bringing up secondary CPUs ... machine # [ 0.406724] smpboot: x86: Booting SMP configuration: machine # [ 0.407415] .... node #0, CPUs: #1 machine # [ 0.408449] smp: Brought up 1 node, 2 CPUs machine # [ 0.409934] smpboot: Total of 2 processors activated (9600.04 BogoMIPS) machine # [ 0.410712] Memory: 2928724K/3145176K available (17215K kernel code, 2726K rwdata, 13584K rodata, 3644K init, 2988K bss, 203700K reserved, 0K cma-reserved) machine # [ 0.412414] devtmpfs: initialized machine # [ 0.413536] x86/mm: Memory block size: 128MB machine # [ 0.416483] posixtimers hash table entries: 1024 (order: 2, 16384 bytes, linear) machine # [ 0.417450] futex hash table entries: 512 (32768 bytes on 1 NUMA nodes, total 32 KiB, linear). machine # [ 0.418509] pinctrl core: initialized pinctrl subsystem machine # [ 0.419734] PM: RTC time: 15:16:11, date: 2026-09-13 machine # [ 0.423108] NET: Registered PF_NETLINK/PF_ROUTE protocol family machine # [ 0.424154] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations machine # [ 0.424440] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations machine # [ 0.425930] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations machine # [ 0.426422] audit: initializing netlink subsys (disabled) machine # [ 0.427439] audit: type=2000 audit(1789312572.010:1): state=initialized audit_enabled=0 res=1 machine # [ 0.427666] thermal_sys: Registered thermal governor 'fair_share' machine # [ 0.428415] thermal_sys: Registered thermal governor 'bang_bang' machine # [ 0.429412] thermal_sys: Registered thermal governor 'step_wise' machine # [ 0.430413] thermal_sys: Registered thermal governor 'user_space' machine # [ 0.431412] thermal_sys: Registered thermal governor 'power_allocator' machine # [ 0.432428] cpuidle: using governor menu machine # [ 0.434607] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 machine # [ 0.435656] PCI: ECAM [mem 0xb0000000-0xbfffffff] (base 0xb0000000) for domain 0000 [bus 00-ff] machine # [ 0.436417] PCI: ECAM [mem 0xb0000000-0xbfffffff] reserved as E820 entry machine # [ 0.437424] PCI: Using configuration type 1 for base access machine # [ 0.438594] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. machine # [ 0.445478] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages machine # [ 0.449413] HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page machine # [ 0.450413] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages machine # [ 0.451413] HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page machine # [ 0.466414] ACPI: Added _OSI(Module Device) machine # [ 0.468421] ACPI: Added _OSI(Processor Device) machine # [ 0.469419] ACPI: Added _OSI(Processor Aggregator Device) machine # [ 0.478879] ACPI: 1 ACPI AML tables successfully acquired and loaded machine # [ 0.483918] ACPI: Interpreter enabled machine # [ 0.485485] ACPI: PM: (supports S0 S3 S4 S5) machine # [ 0.486419] ACPI: Using IOAPIC for interrupt routing machine # [ 0.488668] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug machine # [ 0.492419] PCI: Using E820 reservations for host bridge windows machine # [ 0.494790] ACPI: Enabled 2 GPEs in block 00 to 3F machine # [ 0.504462] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) machine # [ 0.506423] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3] machine # [ 0.509593] acpi PNP0A08:00: _OSC: platform does not support [PCIeHotplug LTR] machine # [ 0.511674] acpi PNP0A08:00: _OSC: OS now controls [PME AER PCIeCapability] machine # [ 0.514844] PCI host bridge to bus 0000:00 machine # [ 0.515417] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] machine # [ 0.516413] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] machine # [ 0.517413] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] machine # [ 0.518412] pci_bus 0000:00: root bus resource [mem 0x80000000-0xafffffff window] machine # [ 0.520412] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] machine # [ 0.521412] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe07ffffffff window] machine # [ 0.522426] pci_bus 0000:00: root bus resource [bus 00-ff] machine # [ 0.523525] pci 0000:00:00.0: [8086:29c0] type 00 class 0x060000 conventional PCI endpoint machine # [ 0.525859] pci 0000:00:01.0: [1234:1111] type 00 class 0x030000 conventional PCI endpoint machine # [ 0.534491] pci 0000:00:01.0: BAR 0 [mem 0xfd000000-0xfdffffff pref] machine # [ 0.535424] pci 0000:00:01.0: BAR 2 [mem 0xfebd0000-0xfebd0fff] machine # [ 0.536435] pci 0000:00:01.0: ROM [mem 0xfebc0000-0xfebcffff pref] machine # [ 0.538606] pci 0000:00:01.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff] machine # [ 0.540125] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint machine # [ 0.544447] pci 0000:00:02.0: BAR 0 [io 0xc140-0xc15f] machine # [ 0.545419] pci 0000:00:02.0: BAR 1 [mem 0xfebd1000-0xfebd1fff] machine # [ 0.546434] pci 0000:00:02.0: BAR 4 [mem 0xe0000000000-0xe0000003fff 64bit pref] machine # [ 0.548419] pci 0000:00:02.0: ROM [mem 0xfeb40000-0xfeb7ffff pref] machine # [ 0.549960] pci 0000:00:03.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint machine # [ 0.553445] pci 0000:00:03.0: BAR 0 [io 0xc160-0xc17f] machine # [ 0.554324] pci 0000:00:03.0: BAR 1 [mem 0xfebd2000-0xfebd2fff] machine # [ 0.555212] pci 0000:00:03.0: BAR 4 [mem 0xe0000004000-0xe0000007fff 64bit pref] machine # [ 0.556910] pci 0000:00:04.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint machine # [ 0.560305] pci 0000:00:04.0: BAR 0 [io 0xc080-0xc0bf] machine # [ 0.561116] pci 0000:00:04.0: BAR 1 [mem 0xfebd3000-0xfebd3fff] machine # [ 0.562434] pci 0000:00:04.0: BAR 4 [mem 0xe0000008000-0xe000000bfff 64bit pref] machine # [ 0.563943] pci 0000:00:05.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint machine # [ 0.568446] pci 0000:00:05.0: BAR 0 [io 0xc180-0xc19f] machine # [ 0.570420] pci 0000:00:05.0: BAR 1 [mem 0xfebd4000-0xfebd4fff] machine # [ 0.571434] pci 0000:00:05.0: BAR 4 [mem 0xe000000c000-0xe000000ffff 64bit pref] machine # [ 0.572961] pci 0000:00:06.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint machine # [ 0.576443] pci 0000:00:06.0: BAR 0 [io 0xc1a0-0xc1bf] machine # [ 0.577338] pci 0000:00:06.0: BAR 1 [mem 0xfebd5000-0xfebd5fff] machine # [ 0.578226] pci 0000:00:06.0: BAR 4 [mem 0xe0000010000-0xe0000013fff 64bit pref] machine # [ 0.580507] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint machine # [ 0.584153] pci 0000:00:07.0: BAR 0 [io 0xc000-0xc07f] machine # [ 0.584419] pci 0000:00:07.0: BAR 1 [mem 0xfebd6000-0xfebd6fff] machine # [ 0.585434] pci 0000:00:07.0: BAR 4 [mem 0xe0000014000-0xe0000017fff 64bit pref] machine # [ 0.588009] pci 0000:00:08.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint machine # [ 0.601443] pci 0000:00:08.0: BAR 0 [io 0xc1c0-0xc1df] machine # [ 0.603419] pci 0000:00:08.0: BAR 1 [mem 0xfebd7000-0xfebd7fff] machine # [ 0.604433] pci 0000:00:08.0: BAR 4 [mem 0xe0000018000-0xe000001bfff 64bit pref] machine # [ 0.605418] pci 0000:00:08.0: ROM [mem 0xfeb80000-0xfebbffff pref] machine # [ 0.607154] pci 0000:00:09.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint machine # [ 0.609448] pci 0000:00:09.0: BAR 1 [mem 0xfebd8000-0xfebd8fff] machine # [ 0.610434] pci 0000:00:09.0: BAR 4 [mem 0xe000001c000-0xe000001ffff 64bit pref] machine # [ 0.613375] pci 0000:00:0a.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint machine # [ 0.616473] pci 0000:00:0a.0: BAR 0 [io 0xc0c0-0xc0ff] machine # [ 0.617402] pci 0000:00:0a.0: BAR 1 [mem 0xfebd9000-0xfebd9fff] machine # [ 0.618281] pci 0000:00:0a.0: BAR 4 [mem 0xe0000020000-0xe0000023fff 64bit pref] machine # [ 0.619992] pci 0000:00:0b.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint machine # [ 0.624319] pci 0000:00:0b.0: BAR 0 [io 0xc1e0-0xc1ff] machine # [ 0.625117] pci 0000:00:0b.0: BAR 1 [mem 0xfebda000-0xfebdafff] machine # [ 0.626434] pci 0000:00:0b.0: BAR 4 [mem 0xe0000024000-0xe0000027fff 64bit pref] machine # [ 0.627998] pci 0000:00:1d.0: [8086:2934] type 00 class 0x0c0300 conventional PCI endpoint machine # [ 0.630123] pci 0000:00:1d.0: BAR 4 [io 0xc200-0xc21f] machine # [ 0.631614] pci 0000:00:1d.1: [8086:2935] type 00 class 0x0c0300 conventional PCI endpoint machine # [ 0.633036] pci 0000:00:1d.1: BAR 4 [io 0xc220-0xc23f] machine # [ 0.635317] pci 0000:00:1d.2: [8086:2936] type 00 class 0x0c0300 conventional PCI endpoint machine # [ 0.637106] pci 0000:00:1d.2: BAR 4 [io 0xc240-0xc25f] machine # [ 0.638626] pci 0000:00:1d.7: [8086:293a] type 00 class 0x0c0320 conventional PCI endpoint machine # [ 0.639999] pci 0000:00:1d.7: BAR 0 [mem 0xfebdb000-0xfebdbfff] machine # [ 0.641711] pci 0000:00:1f.0: [8086:2918] type 00 class 0x060100 conventional PCI endpoint machine # [ 0.643694] pci 0000:00:1f.0: quirk: [io 0x0600-0x067f] claimed by ICH6 ACPI/GPIO/TCO machine # [ 0.644675] pci 0000:00:1f.2: [8086:2922] type 00 class 0x010601 conventional PCI endpoint machine # [ 0.647464] pci 0000:00:1f.2: BAR 4 [io 0xc260-0xc27f] machine # [ 0.648377] pci 0000:00:1f.2: BAR 5 [mem 0xfebdc000-0xfebdcfff] machine # [ 0.650514] pci 0000:00:1f.3: [8086:2930] type 00 class 0x0c0500 conventional PCI endpoint machine # [ 0.652055] pci 0000:00:1f.3: BAR 4 [io 0x0700-0x073f] machine # [ 0.656469] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 machine # [ 0.657528] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 machine # [ 0.658518] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 machine # [ 0.659547] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 machine # [ 0.660511] ACPI: PCI: Interrupt link LNKE configured for IRQ 10 machine # [ 0.661510] ACPI: PCI: Interrupt link LNKF configured for IRQ 10 machine # [ 0.662513] ACPI: PCI: Interrupt link LNKG configured for IRQ 11 machine # [ 0.663514] ACPI: PCI: Interrupt link LNKH configured for IRQ 11 machine # [ 0.665449] ACPI: PCI: Interrupt link GSIA configured for IRQ 16 machine # [ 0.666429] ACPI: PCI: Interrupt link GSIB configured for IRQ 17 machine # [ 0.667429] ACPI: PCI: Interrupt link GSIC configured for IRQ 18 machine # [ 0.668427] ACPI: PCI: Interrupt link GSID configured for IRQ 19 machine # [ 0.669426] ACPI: PCI: Interrupt link GSIE configured for IRQ 20 machine # [ 0.670425] ACPI: PCI: Interrupt link GSIF configured for IRQ 21 machine # [ 0.671425] ACPI: PCI: Interrupt link GSIG configured for IRQ 22 machine # [ 0.672425] ACPI: PCI: Interrupt link GSIH configured for IRQ 23 machine # [ 0.674590] iommu: Default domain type: Translated machine # [ 0.675413] iommu: DMA domain TLB invalidation policy: lazy mode machine # [ 0.676653] ACPI: bus type USB registered machine # [ 0.677484] usbcore: registered new interface driver usbfs machine # [ 0.678428] usbcore: registered new interface driver hub machine # [ 0.679346] usbcore: registered new device driver usb machine # [ 0.681169] NetLabel: Initializing machine # [ 0.682414] NetLabel: domain hash size = 128 machine # [ 0.683158] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO machine # [ 0.683493] NetLabel: unlabeled traffic allowed by default machine # [ 0.684422] PCI: Using ACPI for IRQ routing machine # [ 0.727572] pci 0000:00:01.0: vgaarb: setting as boot VGA device machine # [ 0.728408] pci 0000:00:01.0: vgaarb: bridge control possible machine # [ 0.728408] pci 0000:00:01.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none machine # [ 0.731421] vgaarb: loaded machine # [ 0.732173] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 machine # [ 0.732413] hpet0: 3 comparators, 64-bit 100.000000 MHz counter machine # [ 0.738491] clocksource: Switched to clocksource kvm-clock machine # [ 0.742211] VFS: Disk quotas dquot_6.6.0 machine # [ 0.742922] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) machine # [ 0.744372] pnp: PnP ACPI init machine # [ 0.745199] ACPI: IRQ 4 override to edge(!), high(!) machine # [ 0.746213] system 00:05: [mem 0xb0000000-0xbfffffff window] has been reserved machine # [ 0.747829] pnp: PnP ACPI: found 6 devices machine # [ 0.755482] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns machine # [ 0.757007] clocksource: Switched to clocksource acpi_pm machine # [ 0.758038] NET: Registered PF_INET protocol family machine # [ 0.759468] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear) machine # [ 0.775726] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear) machine # [ 0.777344] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear) machine # [ 0.778742] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear) machine # [ 0.781196] TCP bind hash table entries: 32768 (order: 8, 1048576 bytes, linear) machine # [ 0.782517] TCP: Hash tables configured (established 32768 bind 32768) machine # [ 0.783689] MPTCP token hash table entries: 4096 (order: 5, 98304 bytes, linear) machine # [ 0.785037] UDP hash table entries: 2048 (order: 5, 131072 bytes, linear) machine # [ 0.786175] UDP-Lite hash table entries: 2048 (order: 5, 131072 bytes, linear) machine # [ 0.787579] NET: Registered PF_UNIX/PF_LOCAL protocol family machine # [ 0.788598] NET: Registered PF_XDP protocol family machine # [ 0.789482] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] machine # [ 0.790540] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] machine # [ 0.791598] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] machine # [ 0.792746] pci_bus 0000:00: resource 7 [mem 0x80000000-0xafffffff window] machine # [ 0.793899] pci_bus 0000:00: resource 8 [mem 0xc0000000-0xfebfffff window] machine # [ 0.795073] pci_bus 0000:00: resource 9 [mem 0xe0000000000-0xe07ffffffff window] machine # [ 0.796944] ACPI: \_SB_.GSIA: Enabled at IRQ 16 machine # [ 0.799053] ACPI: \_SB_.GSIB: Enabled at IRQ 17 machine # [ 0.801043] ACPI: \_SB_.GSIC: Enabled at IRQ 18 machine # [ 0.803251] ACPI: \_SB_.GSID: Enabled at IRQ 19 machine # [ 0.804942] PCI: CLS 0 bytes, default 64 machine # [ 0.805792] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) machine # [ 0.806029] Trying to unpack rootfs image as initramfs... machine # [ 0.806880] software IO TLB: mapped [mem 0x000000007a36a000-0x000000007e36a000] (64MB) machine # [ 0.809342] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229842dd0bd, max_idle_ns: 440795319571 ns machine # [ 0.829822] Initialise system trusted keyrings machine # [ 0.830792] workingset: timestamp_bits=40 max_order=20 bucket_order=0 machine # [ 0.841912] Key type asymmetric registered machine # [ 0.842680] Asymmetric key parser 'x509' registered machine # [ 0.843603] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248) machine # [ 0.845027] io scheduler mq-deadline registered machine # [ 0.845831] io scheduler kyber registered machine # [ 0.850346] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled machine # [ 0.851650] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A machine # [ 0.853790] Linux agpgart interface v0.103 machine # [ 0.854627] ACPI: bus type drm_connector registered machine # [ 0.856354] usbcore: registered new interface driver usbserial_generic machine # [ 0.857470] usbserial: USB Serial support registered for generic machine # [ 0.858492] amd_pstate: The CPPC feature is supported but currently disabled by the BIOS. machine # [ 0.858492] Please enable it if your BIOS has the CPPC option. machine # [ 0.860814] amd_pstate: the _CPC object is not present in SBIOS or ACPI disabled machine # [ 0.862262] drop_monitor: Initializing network drop monitor service machine # [ 0.863477] NET: Registered PF_INET6 protocol family machine # [ 0.866181] Segment Routing with IPv6 machine # [ 0.866891] In-situ OAM (IOAM) with IPv6 machine # [ 0.869254] IPI shorthand broadcast: enabled machine # [ 0.873540] sched_clock: Marking stable (721013595, 151963125)->(893958870, -20982150) machine # [ 0.875298] registered taskstats version 1 machine # [ 0.876325] Loading compiled-in X.509 certificates machine # [ 0.886008] Demotion targets for Node 0: null machine # [ 0.887099] Key type .fscrypt registered machine # [ 0.887777] Key type fscrypt-provisioning registered machine # [ 0.888791] ima: No TPM chip found, activating TPM-bypass! machine # [ 0.889758] ima: Allocated hash algorithm: sha1 machine # [ 0.890617] ima: No architecture policies found machine # [ 0.891658] PM: Magic number: 10:306:285 machine # [ 0.894498] RAS: Correctable Errors collector initialized. machine # [ 0.899002] clk: Disabling unused clocks machine # [ 0.899724] PM: genpd: Disabling unused power domains machine # [ 1.056347] Freeing initrd memory: 29080K machine # [ 1.059667] Freeing unused decrypted memory: 2028K machine # [ 1.062324] Freeing unused kernel image (initmem) memory: 3644K machine # [ 1.063454] Write protecting the kernel read-only data: 32768k machine # [ 1.065450] Freeing unused kernel image (text/rodata gap) memory: 1216K machine # [ 1.067024] Freeing unused kernel image (rodata/data gap) memory: 752K machine # [ 1.118252] x86/mm: Checked W+X mappings: passed, no W+X pages found. machine # [ 1.119393] Run /init as init process machine # [ 1.131106] systemd[1]: Inserted module 'autofs4' machine # [ 1.153263] fuse: init (API version 7.45) machine # [ 1.160519] ACPI: \_SB_.GSIG: Enabled at IRQ 22 machine # [ 1.163399] ACPI: \_SB_.GSIH: Enabled at IRQ 23 machine # [ 1.167422] ACPI: \_SB_.GSIE: Enabled at IRQ 20 machine # [ 1.172846] ACPI: \_SB_.GSIF: Enabled at IRQ 21 machine # [ 1.236188] systemd[1]: Successfully made /usr/ read-only. machine # [ 1.571677] systemd[1]: systemd 261.2 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -BTF -XKBCOMMON +UTMP +LIBARCHIVE) machine # [ 1.576747] systemd[1]: Detected virtualization kvm. machine # [ 1.577649] systemd[1]: Detected architecture x86-64. machine # [ 1.578553] systemd[1]: Running in initrd. machine # [ 1.579660] systemd[1]: Initializing machine ID from random generator. machine # [ 1.580893] systemd[1]: Hostname set to . machine # [ 1.678426] systemd[1]: bpf-restrict-fs: LSM BPF program attached machine # [ 1.712118] systemd[1]: Queued start job for default target Initrd Default Target. machine # [ 1.721591] systemd[1]: Created slice Slice /system/modprobe. machine # [ 1.722859] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. machine # [ 1.724349] systemd[1]: Expecting device /dev/disk/by-label/nixos... machine # [ 1.725485] systemd[1]: Reached target Path Units. machine # [ 1.726382] systemd[1]: Reached target Slice Units. machine # [ 1.727290] systemd[1]: Reached target Swaps. machine # [ 1.728097] systemd[1]: Reached target Timer Units. machine # [ 1.729063] systemd[1]: Listening on D-Bus System Message Bus Socket. machine # [ 1.730263] systemd[1]: Listening on Journal Socket (/dev/log). machine # [ 1.731437] systemd[1]: Listening on Journal Sockets. machine # [ 1.732460] systemd[1]: Listening on udev Control Socket. machine # [ 1.733513] systemd[1]: Listening on udev Kernel Socket. machine # [ 1.734521] systemd[1]: Reached target Socket Units. machine # [ 1.736337] systemd[1]: Starting Create List of Static Device Nodes... machine # [ 1.739057] systemd[1]: Starting Load Kernel Module 9pnet_virtio... machine # [ 1.742727] systemd[1]: Starting Load Kernel Module configfs... machine # [ 1.751051] systemd[1]: Starting Journal Service... machine # [ 1.755158] systemd[1]: Starting Load Kernel Modules... machine # [ 1.756159] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 1.770049] systemd[1]: Starting Coldplug All udev Devices... machine # [ 1.774256] systemd[1]: Finished Create List of Static Device Nodes. machine # [ 1.775932] systemd[1]: modprobe@configfs.service: Deactivated successfully. machine # [ 1.783036] systemd[1]: Finished Load Kernel Module configfs. machine # [ 1.784443] systemd[1]: Kernel Configuration File System skipped, unmet condition check ConditionPathExists=/sys/kernel/config machine # [ 1.789032] netfs: FS-Cache loaded machine # [ 1.795418] 9pnet: Installing 9P2000 support machine # [ 1.798149] systemd-journald[76]: Collecting audit messages is disabled. machine # [ 1.800051] systemd[1]: Starting Create Static Device Nodes in /dev gracefully... machine # [ 1.806716] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. machine # [ 1.815528] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev machine # [ 1.821674] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully. machine # [ 1.825491] systemd[1]: Finished Load Kernel Module 9pnet_virtio. machine # [ 1.827557] systemd[1]: Finished Load Kernel Modules. machine # [ 1.832165] systemd[1]: Starting Apply Kernel Variables... machine # [ 1.691878] systemd-modules-load[77]: Using 2[ 1.844060] systemd[1]: Finished Create Static Device Nodes in /dev gracefully. machine # probe threads machine # [ 1.694026] systemd-modules-load[77]: Inserted module 'virtio_balloon' machine # [ 1.695158] systemd-modules-load[77]: Inserted module 'virtio_gpu' machine # [ 1.696214] systemd-modules-load[77]: Inserted module 'dm_mod' machine # [ 1.849332] systemd[1]: Started Journal Service. machine # [ 1.702186] systemd[1]: Finished Apply Kernel Variables. machine # [ 1.708176] systemd[1]: Starting Create Static Device Nodes in /dev... machine # [ 1.719344] systemd[1]: Finished Create Static Device Nodes in /dev. machine # [ 1.721068] systemd[1]: Reached target Preparation for Local File Systems. machine # [ 1.721991] systemd[1]: Reached target Local File Systems. machine # [ 1.725901] systemd[1]: Starting Create System Files and Directories... machine # [ 1.727037] systemd[1]: Starting Rule-based Manager for Device Events and Files... machine # [ 1.746148] systemd[1]: Finished Create System Files and Directories. machine # [ 1.753367] systemd-udevd[94]: Using default interface naming scheme 'v261'. machine # [ 1.769302] systemd[1]: Started Rule-based Manager for Device Events and Files. machine # [ 1.775585] systemd[1]: Finished Coldplug All udev Devices. machine # [ 1.776401] systemd[1]: Reached target System Initialization. machine # [ 1.777165] systemd[1]: Reached target Basic System. machine # [ 2.051808] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 machine # [ 2.059683] serio: i8042 KBD port at 0x60,0x64 irq 1 machine # [ 2.060430] serio: i8042 AUX port at 0x60,0x64 irq 12 machine # [ 2.076741] uhci_hcd 0000:00:1d.0: UHCI Host Controller machine # [ 2.080895] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 1 machine # [ 2.088880] virtio_blk virtio5: 2/0/0 default/read/poll queues machine # [ 2.089012] uhci_hcd 0000:00:1d.0: detected 2 ports machine # [ 2.096502] uhci_hcd 0000:00:1d.0: irq 16, io port 0x0000c200 machine # [ 2.099565] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.18 machine # [ 2.100840] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 machine # [ 2.102179] usb usb1: Product: UHCI Host Controller machine # [ 2.102854] usb usb1: Manufacturer: Linux 6.18.49 uhci_hcd machine # [ 2.104788] usb usb1: SerialNumber: 0000:00:1d.0 machine # [ 2.107835] SCSI subsystem initialized machine # [ 2.108934] hub 1-0:1.0: USB hub found machine # [ 2.110374] hub 1-0:1.0: 2 ports detected machine # [ 2.111482] virtio_blk virtio5: [vda] 16777216 512-byte logical blocks (8.59 GB/8.00 GiB) machine # [ 2.115099] ehci-pci 0000:00:1d.7: EHCI Host Controller machine # [ 2.115889] ehci-pci 0000:00:1d.7: new USB bus registered, assigned bus number 2 machine # [ 2.119335] ehci-pci 0000:00:1d.7: irq 19, io mem 0xfebdb000 machine # [ 2.126152] ehci-pci 0000:00:1d.7: USB 2.0 started, EHCI 1.00 machine # [ 2.127863] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.18 machine # [ 2.129951] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 machine # [ 2.130991] usb usb2: Product: EHCI Host Controller machine # [ 2.131673] usb usb2: Manufacturer: Linux 6.18.49 ehci_hcd machine # [ 2.133748] usb usb2: SerialNumber: 0000:00:1d.7 machine # [ 1.982349] (udev-worker)[101]: Network interface NamePolicy= disabled on kernel command line.[ 2.135714] hub 2-0:1.0: USB hub found machine # machine # [ 2.136656] hub 2-0:1.0: 6 ports detected machine # [ 1.990159] systemd[1]: Starting Virtual Console Setup... machine # [ 2.160195] hub 1-0:1.0: USB hub found machine # [ 2.160923] hub 1-0:1.0: 2 ports detected machine # [ 2.164629] uhci_hcd 0000:00:1d.1: UHCI Host Controller machine # [ 2.167036] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0 machine # [ 2.170553] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3 machine # [ 2.171635] uhci_hcd 0000:00:1d.1: detected 2 ports machine # [ 2.019834] systemd-vconsole-setup[121]: Configuration of first virtual console was skipped, ignoring remaining ones. machine # [ 2.022161] (udev-worker)[114]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name. machine # [ 2.024513] (udev-worker)[114]: Network interface NamePolicy= disabled on kernel command line. machine # [ 2.027167] systemd[1]: Finished Virtual Console Setup. machine # [ 2.184267] uhci_hcd 0000:00:1d.1: irq 17, io port 0x0000c220 machine # [ 2.189651] usb usb3: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.18 machine # [ 2.190822] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1 machine # [ 2.041406] systemd[1]: Found device /dev/disk/by-label/nixos. machine # [ 2.042631] systemd[1]: Reached target Initrd Root Device. machine # [ 2.195355] usb usb3: Product: UHCI Host Controller machine # [ 2.196039] usb usb3: Manufacturer: Linux 6.18.49 uhci_hcd machine # [ 2.196760] usb usb3: SerialNumber: 0000:00:1d.1 machine # [ 2.043649] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos... machine # [ 2.200170] hub 3-0:1.0: USB hub found machine # [ 2.200769] hub 3-0:1.0: 2 ports detected machine # [ 2.205600] uhci_hcd 0000:00:1d.2: UHCI Host Controller machine # [ 2.206338] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4 machine # [ 2.209124] uhci_hcd 0000:00:1d.2: detected 2 ports machine # [ 2.209909] uhci_hcd 0000:00:1d.2: irq 18, io port 0x0000c240 machine # [ 2.211311] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.18 machine # [ 2.212619] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1 machine # [ 2.213916] usb usb4: Product: UHCI Host Controller machine # [ 2.214805] usb usb4: Manufacturer: Linux 6.18.49 uhci_hcd machine # [ 2.215656] usb usb4: SerialNumber: 0000:00:1d.2 machine # [ 2.216883] hub 4-0:1.0: USB hub found machine # [ 2.216911] hub 4-0:1.0: 2 ports detected machine # [ 2.078326] systemd-fsck[129]: nixos: clean, 12/524288 files, 58513/2097152 blocks machine # [ 2.234034] ahci 0000:00:1f.2: AHCI vers 0001.0000, 32 command slots, 1.5 Gbps, SATA mode machine # [ 2.084228] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos. machine # [ 2.238795] ahci 0000:00:1f.2: 6/6 ports implemented (port mask 0x3f) machine # [ 2.240422] ahci 0000:00:1f.2: flags: 64bit ncq only machine # [ 2.244290] scsi host0: ahci machine # [ 2.245470] scsi host1: ahci machine # [ 2.246580] scsi host2: ahci machine # [ 2.247400] scsi host3: ahci machine # [ 2.248716] scsi host4: ahci machine # [ 2.249649] scsi host5: ahci machine # [ 2.250643] ata1: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc100 irq 45 lpm-pol 1 machine # [ 2.252199] ata2: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc180 irq 45 lpm-pol 1 machine # [ 2.253495] ata3: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc200 irq 45 lpm-pol 1 machine # [ 2.254635] ata4: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc280 irq 45 lpm-pol 1 machine # [ 2.255782] ata5: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc300 irq 45 lpm-pol 1 machine # [ 2.257363] ata6: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc380 irq 45 lpm-pol 1 machine # [ 2.380144] usb 2-1: new high-speed USB device number 2 using ehci-pci machine # [ 2.511410] usb 2-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 machine # [ 2.514321] usb 2-1: New USB device strings: Mfr=1, Product=3, SerialNumber=10 machine # [ 2.516953] usb 2-1: Product: QEMU USB Tablet machine # [ 2.518589] usb 2-1: Manufacturer: QEMU machine # [ 2.520039] usb 2-1: SerialNumber: 28754-0000:00:1d.7-1 machine # [ 2.552234] hid: raw HID events driver (C) Jiri Kosina machine # [ 2.569208] ata6: SATA link down (SStatus 0 SControl 300) machine # [ 2.571478] ata2: SATA link down (SStatus 0 SControl 300) machine # [ 2.573706] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300) machine # [ 2.576399] ata1: SATA link down (SStatus 0 SControl 300) machine # [ 2.578383] ata3.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100 machine # [ 2.580635] ata3.00: applying bridge limits machine # [ 2.582596] ata5: SATA link down (SStatus 0 SControl 300) machine # [ 2.584594] ata3.00: configured for UDMA/100 machine # [ 2.586516] ata4: SATA link down (SStatus 0 SControl 300) machine # [ 2.589394] scsi 2:0:0:0: CD-ROM QEMU QEMU DVD-ROM 2.5+ PQ: 0 ANSI: 5 machine # [ 2.637306] usbcore: registered new interface driver usbhid machine # [ 2.638851] usbhid: USB HID core driver machine # [ 2.648127] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:1d.7/usb2/2-1/2-1:1.0/0003:0627:0001.0001/input/input2 machine # [ 2.650537] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:1d.7-1/input0 machine # [ 2.677244] sr 2:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray machine # [ 2.701423] cdrom: Uniform CD-ROM driver Revision: 3.20 machine # [ 2.622328] systemd[1]: Mounting /sysroot... machine # [ 2.880799] EXT4-fs (vda): mounted filesystem 7dcebace-693b-40e4-9567-e02b02c81a92 r/w with ordered data mode. Quota mode: none. machine # [ 2.734853] systemd[1]: Mounted /sysroot. machine # [ 2.736147] systemd[1]: Reached target Initrd Root File System. machine # [ 2.741338] systemd[1]: Mounting /sysroot/nix/.ro-store... machine # [ 2.752510] systemd[1]: Mounting /sysroot/nix/.rw-store... machine # [ 2.755826] systemd[1]: Mounting /sysroot/run... machine # [ 2.761230] systemd[1]: Mounting /sysroot/tmp/shared... machine # [ 2.764613] systemd[1]: Mounting /sysroot/tmp/xchg... machine # [ 2.931015] 9p: Installing v9fs 9p2000 file system support machine # [ 2.779914] systemd[1]: Starting Mountpoints Configured in the Real Root... machine # [ 2.785317] systemd[1]: Mounted /sysroot/nix/.rw-store. machine # [ 2.786841] systemd[1]: Mounted /sysroot/tmp/xchg. machine # [ 2.788275] systemd[1]: Mounted /sysroot/nix/.ro-store. machine # [ 2.791150] systemd[1]: Mounted /sysroot/tmp/shared. machine # [ 2.796510] systemd-sysroot-fstab-check[171]: /sysroot should be mounted in the initrd, will request daemon-reload. machine # [ 2.798615] systemd[1]: Mounted /sysroot/run. machine # [ 2.802206] systemd[1]: Starting rw-sysroot-nix-store.service... machine # [ 2.803377] systemd[1]: Reload requested from client PID 171 ('systemd-sysroot') (unit initrd-parse-etc.service)... machine # [ 2.804808] systemd[1]: Reloading... machine # [ 2.863159] systemd[1]: Reloading finished in 58 ms. machine # [ 2.880938] systemd-sysroot-fstab-check[171]: Requesting initrd-fs.target/start/replace... machine # [ 2.883457] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully. machine # [ 2.885412] systemd[1]: Finished rw-sysroot-nix-store.service. machine # [ 2.886970] systemd-sysroot-fstab-check[171]: Requesting swap.target/start/replace... machine # [ 2.889118] systemd[1]: initrd-parse-etc.service: Deactivated successfully. machine # [ 2.890942] systemd[1]: Finished Mountpoints Configured in the Real Root. machine # [ 2.892874] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies. machine # [ 2.894856] systemd[1]: Starting rw-sysroot-nix-store.service... machine # [ 2.906584] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully. machine # [ 2.908274] systemd[1]: Finished rw-sysroot-nix-store.service. machine # [ 3.623369] systemd[1]: Mounting /sysroot/nix/store... machine # [ 3.678939] systemd[1]: Mounted /sysroot/nix/store. machine # [ 3.680685] systemd[1]: Reached target Initrd File Systems. machine # [ 3.684183] systemd[1]: Starting Find NixOS closure... machine # [ 3.686300] systemd[1]: Starting Create Volatile Files and Directories in the Real Root... machine # [ 3.717509] systemd[1]: Finished Create Volatile Files and Directories in the Real Root. machine # [ 3.720241] systemd[1]: sysroot-run-credentials-systemd\x2dtmpfiles\x2dsetup\x2dsysroot.service.mount: Deactivated successfully. machine # [ 3.739055] systemd[1]: Finished Find NixOS closure. machine # [ 3.740552] systemd[1]: Reached target Initrd Default Target. machine # [ 3.742201] systemd[1]: Starting Cleaning Up and Shutting Down Daemons... machine # [ 3.765151] systemd[1]: Stopped target Initrd Default Target. machine # [ 3.767259] systemd[1]: Stopped target Basic System. machine # [ 3.768742] systemd[1]: Stopped target Initrd Root Device. machine # [ 3.770202] systemd[1]: Stopped target Path Units. machine # [ 3.771456] systemd[1]: systemd-ask-password-console.path: Deactivated successfully. machine # [ 3.773877] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch. machine # [ 3.776082] systemd[1]: Stopped target Slice Units. machine # [ 3.777525] systemd[1]: Stopped target Socket Units. machine # [ 3.779151] systemd[1]: Stopped target System Initialization. machine # [ 3.780976] systemd[1]: Stopped target Swaps. machine # [ 3.782105] systemd[1]: Stopped target Timer Units. machine # [ 3.783374] systemd[1]: dbus.socket: Deactivated successfully. machine # [ 3.784724] systemd[1]: Closed D-Bus System Message Bus Socket. machine # [ 3.786144] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully. machine # [ 3.787639] systemd[1]: Stopped Find NixOS closure. machine # [ 3.790455] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio machine # [ 3.792382] systemd[1]: Starting rw-sysroot-nix-store.service... machine # [ 3.793839] systemd[1]: systemd-sysctl.service: Deactivated successfully. machine # [ 3.794792] systemd[1]: Stopped Apply Kernel Variables. machine # [ 3.795583] systemd[1]: systemd-modules-load.service: Deactivated successfully. machine # [ 3.796589] systemd[1]: Stopped Load Kernel Modules. machine # [ 3.797351] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully. machine # [ 3.798382] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root. machine # [ 3.799428] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully. machine # [ 3.802553] systemd[1]: Stopped Create System Files and Directories. machine # [ 3.803739] systemd[1]: Stopped target Local File Systems. machine # [ 3.804574] systemd[1]: Stopped target Preparation for Local File Systems. machine # [ 3.805603] systemd[1]: systemd-udev-trigger.service: Deactivated successfully. machine # [ 3.806664] systemd[1]: Stopped Coldplug All udev Devices. machine # [ 3.807487] systemd[1]: Stopping Rule-based Manager for Device Events and Files... machine # [ 3.808530] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 3.809551] systemd[1]: Stopped Virtual Console Setup. machine # [ 3.810333] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully. machine # [ 3.811231] systemd[1]: Finished rw-sysroot-nix-store.service. machine # [ 3.812022] systemd[1]: initrd-cleanup.service: Deactivated successfully. machine # [ 3.812895] systemd[1]: Finished Cleaning Up and Shutting Down Daemons. machine # [ 3.815836] systemd[1]: systemd-udevd.service: Deactivated successfully. machine # [ 3.816834] systemd[1]: Stopped Rule-based Manager for Device Events and Files. machine # [ 3.817771] systemd[1]: systemd-udevd-control.socket: Deactivated successfully. machine # [ 3.818725] systemd[1]: Closed udev Control Socket. machine # [ 3.819440] systemd[1]: Starting Cleanup udev Database... machine # [ 3.820229] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully. machine # [ 3.821249] systemd[1]: Stopped Create Static Device Nodes in /dev. machine # [ 3.822083] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully. machine # [ 3.823100] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully. machine # [ 3.823983] systemd[1]: kmod-static-nodes.service: Deactivated successfully. machine # [ 3.824881] systemd[1]: Stopped Create List of Static Device Nodes. machine # [ 3.836615] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully. machine # [ 3.837799] systemd[1]: Finished Cleanup udev Database. machine # [ 3.838590] systemd[1]: Reached target Switch Root. machine # [ 3.839347] systemd[1]: Starting NixOS Activation... machine # [ 4.005248] initrd-nixos-activation-start[218]: booting system configuration /nix/store/2j5h69yyypr6ipr8f13644brlzqaxd9q-nixos-system-machine-test machine # [ 4.070744] initrd-nixos-activation-start[218]: running activation script... machine # [ 4.511603] initrd-nixos-activation-start[241]: setting up /etc... machine # [ 4.779022] systemd[1]: initrd-nixos-activation.service: Deactivated successfully. machine # [ 4.780081] systemd[1]: Finished NixOS Activation. machine # [ 4.782088] systemd[1]: Starting Switch Root... machine # [ 4.800990] systemd[1]: Switching root. machine # [ 4.989950] systemd-journald[76]: Received SIGTERM from PID 1 (systemd). machine # [ 5.132339] NET: Registered PF_VSOCK protocol family machine # [ 5.537193] systemd[1]: systemd 261.2 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -BTF -XKBCOMMON +UTMP +LIBARCHIVE) machine # [ 5.546743] systemd[1]: Detected virtualization kvm. machine # [ 5.548553] systemd[1]: Detected architecture x86-64. machine # [ 5.550487] systemd[1]: Detected first boot. machine # [ 5.556772] systemd[1]: Initializing machine ID from random generator. machine # [ 5.705674] systemd[1]: bpf-restrict-fs: LSM BPF program attached machine # [ 5.827407] systemd[1]: Applying preset policy. machine # [ 6.324759] systemd[1]: Populated /etc with preset unit settings. machine # [ 6.867320] systemd[1]: initrd-switch-root.service: Deactivated successfully. machine # [ 6.868698] systemd[1]: Stopped initrd-switch-root.service. machine # [ 6.871397] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. machine # [ 6.873625] systemd[1]: Created slice Slice /system/getty. machine # [ 6.875011] systemd[1]: Created slice User and Session Slice. machine # [ 6.875863] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. machine # [ 6.877062] systemd[1]: Started Forward Password Requests to Wall Directory Watch. machine # [ 6.878153] systemd[1]: Expecting device /dev/hvc0... machine # [ 6.878853] systemd[1]: Expecting device /dev/ttyS0... machine # [ 6.879616] systemd[1]: Reached target Local Encrypted Volumes. machine # [ 6.880458] systemd[1]: Stopped target initrd-fs.target. machine # [ 6.881199] systemd[1]: Stopped target initrd-root-fs.target. machine # [ 6.881973] systemd[1]: Stopped target initrd-switch-root.target. machine # [ 6.882817] systemd[1]: Reached target Virtual Machines and Containers. machine # [ 6.883802] systemd[1]: Reached target Path Units. machine # [ 6.884571] systemd[1]: Reached target Remote File Systems. machine # [ 6.885377] systemd[1]: Reached target Slice Units. machine # [ 6.886070] systemd[1]: Reached target Swaps. machine # [ 6.889567] systemd[1]: Listening on Query the User Interactively for a Password. machine # [ 6.893668] systemd[1]: Listening on Process Core Dump Socket. machine # [ 6.896858] systemd[1]: Listening on Credential Encryption/Decryption. machine # [ 6.899877] systemd[1]: Listening on Factory Reset Management. machine # [ 6.900806] systemd[1]: Listening on Hostname Service Socket. machine # [ 6.905027] systemd[1]: Starting Journal Log Access Socket... machine # [ 6.906380] systemd[1]: Listening on Journal Audit Socket. machine # [ 6.909522] systemd[1]: Listening on Console Output Muting Service Socket. machine # [ 6.911002] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket. machine # [ 6.912695] systemd[1]: TPM PCR Measurements skipped, unmet condition check ConditionSecurity=measured-os machine # [ 6.913995] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki machine # [ 6.924226] systemd[1]: Listening on Disk Repartitioning Service Socket. machine # [ 6.925226] systemd[1]: Listening on udev Control Socket. machine # [ 6.926091] systemd[1]: Listening on udev Varlink Socket. machine # [ 6.930002] systemd[1]: Mounting Huge Pages File System... machine # [ 6.932759] systemd[1]: Mounting POSIX Message Queue File System... machine # [ 6.936486] systemd[1]: Mounting Kernel Debug File System... machine # [ 6.939534] systemd[1]: Mounting Kernel Trace File System... machine # [ 6.944277] systemd[1]: Starting Create List of Static Device Nodes... machine # [ 6.948071] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio machine # [ 6.952810] systemd[1]: Starting Load Kernel Module configfs... machine # [ 6.954135] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm machine # [ 6.956658] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore machine # [ 6.959593] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse machine # [ 6.963091] systemd[1]: Mounting FUSE Control File System... machine # [ 6.965224] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67 machine # [ 6.972591] systemd[1]: Starting Journal Service... machine # [ 7.003880] systemd[1]: Starting Load Kernel Modules... machine # [ 7.008491] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer... machine # [ 7.014808] systemd[1]: Starting Remount Root and Kernel File Systems... machine # [ 7.017299] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 7.023473] systemd[1]: Starting Coldplug All udev Devices... machine # [ 7.028416] systemd[1]: Listening on Journal Log Access Socket. machine # [ 7.041713] systemd[1]: Mounted Huge Pages File System. machine # [ 7.044427] systemd[1]: Mounted POSIX Message Queue File System. machine # [ 7.047872] systemd[1]: Mounted Kernel Debug File System. machine # [ 7.051612] systemd[1]: Mounted Kernel Trace File System. machine # [ 7.053224] systemd[1]: Mounted FUSE Control File System. machine # [ 7.056328] systemd[1]: Finished Create List of Static Device Nodes. machine # [ 7.061156] systemd[1]: Starting Create Static Device Nodes in /dev gracefully... machine # [ 7.076579] systemd[1]: modprobe@configfs.service: Deactivated successfully. machine # [ 7.079987] systemd[1]: Finished Load Kernel Module configfs. machine # [ 7.097032] systemd-journald[311]: Collecting audit messages is enabled. machine # [ 7.110040] EXT4-fs (vda): re-mounted 7dcebace-693b-40e4-9567-e02b02c81a92. machine # [ 7.114566] systemd[1]: Finished Remount Root and Kernel File Systems. machine # [ 7.116343] systemd[1]: Listening on Disk Image Download Service Socket. machine # [ 7.119057] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore machine # [ 7.124039] systemd[1]: Starting Load/Save OS Random Seed... machine # [ 7.124840] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 7.136134] loop: module loaded machine # [ 7.142883] systemd[1]: Finished Load Kernel Modules. machine # [ 6.992580] systemd[1]: Queued start job for default target Multi-User System. machine # [ 7.146060] systemd[1]: Started Journal Service. machine # [ 6.994631] systemd[1]: systemd-journald.service: Deactivated successfully. machine # [ 6.998893] systemd-modules-load[312]: Using 2 probe threads machine # [ 7.001948] systemd-modules-load[312]: Inserted module 'loop' machine # [ 7.015488] systemd-oomd[313]: No swap; memory pressure usage will be degraded machine # [ 7.020168] systemd[1]: Starting Flush Journal to Persistent Storage... machine # [ 7.023927] systemd[1]: Starting Apply Kernel Variables... machine # [ 7.026334] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer. machine # [ 7.028327] systemd[1]: Finished Create Static Device Nodes in /dev gracefully. machine # [ 7.031257] systemd[1]: Starting Create Static Device Nodes in /dev... machine # [ 7.035487] systemd[1]: Finished Load/Save OS Random Seed. machine # [ 7.036803] systemd[1]: Reached target First Boot Complete. machine # [ 7.206324] systemd-journald[311]: Received client request to flush runtime journal. machine # [ 7.106843] systemd[1]: Finished Apply Kernel Variables. machine # [ 7.108671] systemd[1]: Finished Create Static Device Nodes in /dev. machine # [ 7.109640] systemd[1]: Reached target Preparation for Local File Systems. machine # [ 7.110568] systemd[1]: Starting Rule-based Manager for Device Events and Files... machine # [ 7.111589] systemd[1]: Finished Flush Journal to Persistent Storage. machine # [ 7.135934] systemd[1]: Finished Coldplug All udev Devices. machine # [ 7.184692] systemd-udevd[339]: Using default interface naming scheme 'v261'. machine # [ 7.279759] systemd[1]: Started Rule-based Manager for Device Events and Files. machine # [ 7.334847] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs machine # [ 7.353705] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs machine # [ 7.366168] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse machine # [ 7.391519] systemd[1]: Condition check resulted in /dev/hvc0 being skipped. machine # [ 7.415654] systemd[1]: Condition check resulted in /dev/ttyS0 being skipped. machine # [ 7.423632] (udev-worker)[348]: Network interface NamePolicy= disabled on kernel command line. machine # [ 7.428364] (udev-worker)[346]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name. machine # [ 7.430793] (udev-worker)[346]: Network interface NamePolicy= disabled on kernel command line. machine # [ 7.474052] systemd[1]: Condition check resulted in Virtio network device being skipped. machine # [ 7.475795] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs machine # [ 7.477968] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore machine # [ 7.480140] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67 machine # [ 7.482603] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore machine # [ 7.484145] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 7.485854] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os machine # [ 7.656408] input: QEMU Virtio Keyboard as /devices/pci0000:00/0000:00:09.0/virtio7/input/input3 machine # [ 7.659392] bochs-drm 0000:00:01.0: vgaarb: deactivate vga console machine # [ 7.676364] Console: switching to colour dummy device 80x25 machine # [ 7.677429] [drm] Found bochs VGA, ID 0xb0c5. machine # [ 7.677431] [drm] Framebuffer size 16384 kB @ 0xfd000000, mmio @ 0xfebd0000. machine # [ 7.679149] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input4 machine # [ 7.679177] bochs-drm 0000:00:01.0: [drm] Registered 1 planes with drm panic machine # [ 7.680699] [drm] Initialized bochs-drm 1.0.0 for 0000:00:01.0 on minor 0 machine # [ 7.691501] lpc_ich 0000:00:1f.0: I/O space for GPIO uninitialized machine # [ 7.692031] ACPI: button: Power Button [PWRF] machine # [ 7.692116] mousedev: PS/2 mouse device common for all mice machine # [ 7.702693] Console: switching to colour frame buffer device 160x50 machine # [ 7.706754] bochs-drm 0000:00:01.0: [drm] fb0: bochs-drmdrmfb frame buffer device machine # [ 7.730232] rtc_cmos 00:04: RTC can wake from S4 machine # [ 7.733212] rtc_cmos 00:04: registered as rtc0 machine # [ 7.733819] rtc_cmos 00:04: setting system clock to 2026-09-13T15:16:19 UTC (1789312579) machine # [ 7.741475] rtc_cmos 00:04: alarms up to one day, y3k, 242 bytes nvram, hpet irqs machine # [ 7.758359] parport_pc 00:02: reported by Plug and Play ACPI machine # [ 7.760649] parport0: PC-style at 0x378, irq 7 [PCSPP(,...)] machine # [ 7.777150] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input6 machine # [ 7.779597] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input5 machine # [ 7.783789] i801_smbus 0000:00:1f.3: SMBus using PCI interrupt machine # [ 7.784608] i2c i2c-0: Memory type 0x07 not supported yet, not instantiating SPD machine # [ 7.848617] iTCO_wdt iTCO_wdt.0.auto: Found a ICH9 TCO device (Version=2, TCOBASE=0x0660) machine # [ 7.700277] systemd[1]: Starting Virtual Console Setup... machine # [ 7.710463] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 7.711545] systemd[1]: Stopped Virtual Console Setup. machine # [ 7.715949] systemd[1]: Starting Virtual Console Setup... machine # [ 7.719544] systemd[1]: Mounting /run/wrappers... machine # [ 7.721695] systemd[1]: Mounting Kernel Configuration File System... machine # [ 7.880005] ppdev: user-space parallel port driver machine # [ 7.880790] iTCO_wdt iTCO_wdt.0.auto: initialized. heartbeat=30 sec (nowayout=0) machine # [ 7.753760] systemd[1]: Mounted Kernel Configuration File System. machine # [ 7.757551] systemd[1]: Mounted /run/wrappers. machine # [ 7.759619] systemd[1]: Reached target Local File Systems. machine # [ 7.764604] systemd[1]: Listening on Boot Loader Control Service Socket. machine # [ 7.766366] systemd[1]: Starting register-nix-paths.service... machine # [ 7.770124] systemd[1]: Starting Create SUID/SGID Wrappers... machine # [ 7.773220] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met. machine # [ 7.778169] systemd[1]: Starting Save Transient machine-id to Disk... machine # [ 7.781104] systemd[1]: Starting Create System Files and Directories... machine # [ 7.790703] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 7.792634] systemd[1]: Stopped Virtual Console Setup. machine # [ 7.799683] systemd[1]: Starting Virtual Console Setup... machine # [ 7.847531] systemd[1]: Finished Save Transient machine-id to Disk. machine # [ 8.015575] kvm_amd: TSC scaling supported machine # [ 8.016319] kvm_amd: Nested Virtualization enabled machine # [ 8.016855] kvm_amd: Nested Paging enabled machine # [ 8.017650] kvm_amd: LBR virtualization supported machine # [ 8.018523] kvm_amd: Virtual VMLOAD VMSAVE supported machine # [ 8.019231] kvm_amd: Virtual GIF supported machine # [ 8.019743] kvm_amd: Virtual NMI enabled machine # [ 7.904199] systemd[1]: Finished Create System Files and Directories. machine # [ 8.057370] EDAC MC: Ver: 3.0.0 machine # [ 7.908091] systemd[1]: Starting Rebuild Journal Catalog... machine # [ 7.910241] systemd[1]: Starting Record System Boot/Shutdown in UTMP... machine # [ 7.946553] systemd[1]: Finished Record System Boot/Shutdown in UTMP. machine # [ 7.979633] systemd[1]: Finished Rebuild Journal Catalog. machine # [ 7.982471] systemd[1]: Starting Update is Completed... machine # [ 8.010262] systemd[1]: Finished Update is Completed. machine # [ 8.176186] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully. machine # [ 8.177673] systemd[1]: Finished Create SUID/SGID Wrappers. machine # [ 8.249954] systemd-vconsole-setup[389]: Configuration of first virtual console was skipped, ignoring remaining ones. machine # [ 8.253219] systemd[1]: Finished Virtual Console Setup. machine # [ 8.348381] systemd[1]: Finished register-nix-paths.service. machine # [ 8.349344] systemd[1]: Reached target System Initialization. machine # [ 8.350459] systemd[1]: Started Discard unused filesystem blocks once a week. machine # [ 8.351441] systemd[1]: Started Daily Cleanup of Temporary Directories. machine # [ 8.352372] systemd[1]: Reached target Timer Units. machine # [ 8.353120] systemd[1]: Listening on D-Bus System Message Bus Socket. machine # [ 8.354024] systemd[1]: Listening on Nix Daemon Socket. machine # [ 8.354865] systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. machine # [ 8.355957] systemd[1]: Reached target Socket Units. machine # [ 8.356680] systemd[1]: Reached target Basic System. machine # [ 8.359584] systemd[1]: Started backdoor.service. machine # [ 8.363812] systemd[1]: Starting Import lastlog data into lastlog2 database... machine # [ 8.366135] systemd[1]: Starting Name Service Cache Daemon (nsncd)... machine # [ 8.372491] systemd[1]: Starting Post-Boot Actions... machine # [ 8.375439] systemd[1]: Started Reset console on configuration changes. machine # [ 8.378872] systemd[1]: Starting resolvconf update... machine # [ 8.381985] systemd[1]: Started rustfs.service. machine # [ 8.385624] systemd[1]: Starting rustfs-setup.service... machine # [ 8.392383] systemd[1]: Starting D-Bus System Message Bus... machine # [ 8.427304] systemd[1]: Finished Post-Boot Actions. machine # [ 8.457395] systemd[1]: Started Name Service Cache Daemon (nsncd). machine # [ 8.461192] systemd[1]: Reached target Host and Network Name Lookups. machine # connecting to host... machine # [ 8.463050] nsncd[464]: Sep 13 15:16:20.371 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" machine # [ 8.466235] systemd[1]: Reached target User and Group Name Lookups. machine # [ 8.467752] systemd[1]: Starting User Login Management... machine # [ 8.470374] systemd[1]: Finished Import lastlog data into lastlog2 database. machine: Guest shell says: b'Spawning backdoor root shell...\n' machine: connected to guest root shell machine: (connecting took 9.13 seconds) machine: (finished: waiting for the VM to finish booting, in 9.38 seconds) machine # [ 8.524765] dbus-broker-launch[471]: Looking up NSS user entry for 'systemd-timesync'... machine # [ 8.530493] systemd-logind[484]: New seat seat0. machine # [ 8.538070] systemd-logind[484]: Watching system buttons on /dev/input/event3 (Power Button) machine # [ 8.540068] systemd-logind[484]: Watching system buttons on /dev/input/event2 (QEMU Virtio Keyboard) machine # [ 8.547455] systemd-logind[484]: Watching system buttons on /dev/input/event0 (AT Translated Set 2 keyboard) machine # [ 8.550530] systemd[1]: Started User Login Management. machine # [ 8.557597] systemd[1]: Starting linger-users.service... machine # [ 8.557950] dbus-broker-launch[471]: NSS returned no entry for 'systemd-timesync' machine # [ 8.558547] dbus-broker-launch[471]: Invalid user-name in /nix/store/9rxjqx0f67558aqal3fgk79jdf7g092c-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" machine # [ 8.603338] systemd[1]: Started D-Bus System Message Bus. machine # [ 8.604185] systemd[1]: linger-users.service: Deactivated successfully. machine # [ 8.605063] systemd[1]: Finished linger-users.service. machine # [ 8.610169] systemd[1]: Stopped target Host and Network Name Lookups. machine # [ 8.611797] systemd[1]: Stopping Host and Network Name Lookups... machine # [ 8.613282] systemd[1]: Stopped target User and Group Name Lookups. machine # [ 8.614478] systemd[1]: Stopping User and Group Name Lookups... machine # [ 8.616427] dbus-broker-launch[471]: Ready machine # [ 8.620369] systemd[1]: Stopping Name Service Cache Daemon (nsncd)... machine # [ 8.624621] systemd[1]: nscd.service: Deactivated successfully. machine # [ 8.626320] systemd[1]: Stopped Name Service Cache Daemon (nsncd). machine # [ 8.633708] systemd[1]: Starting Name Service Cache Daemon (nsncd)... machine # [ 8.679024] nsncd[555]: Sep 13 15:16:20.596 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" machine # [ 8.681936] systemd[1]: Started Name Service Cache Daemon (nsncd). machine # [ 8.683299] systemd[1]: Reached target Host and Network Name Lookups. machine # [ 8.684333] systemd[1]: Reached target User and Group Name Lookups. machine # [ 8.694875] systemd[1]: Finished resolvconf update. machine # [ 8.696648] systemd[1]: Reached target Preparation for Network. machine # [ 8.701185] systemd[1]: Starting DHCP Client... machine # [ 8.704745] systemd[1]: Starting Address configuration of eth1... machine # [ 8.708151] systemd[1]: Starting Extra networking commands.... machine # [ 8.716480] systemd[1]: etc-machine\x2did.mount: Deactivated successfully. machine # [ 8.794958] network-addresses-eth1-start[587]: adding address 192.168.1.1/24... done machine # [ 8.805720] network-addresses-eth1-start[587]: adding address 2001:db8:1::1/64... done machine # [ 8.819813] systemd[1]: Finished Address configuration of eth1. machine # [ 8.831463] dhcpcd[599]: dhcpcd-10.3.2 starting machine # [ 8.838847] dhcpcd[647]: dev: loaded udev machine # [ 9.008678] 8021q: 802.1Q VLAN Support v1.8 machine # [ 9.009828] 8021q: adding VLAN 0 to HW filter on device eth1 machine # [ 8.860858] systemd[1]: Finished Extra networking commands.. machine # [ 8.862885] systemd[1]: Reached target Network. machine # [ 8.868476] systemd[1]: Starting PostgreSQL Server... machine # [ 8.869733] systemd[1]: Starting Permit User Sessions... machine # [ 8.896799] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. machine # [ 8.908067] systemd[1]: Finished Permit User Sessions. machine # [ 8.910759] systemd[1]: Started Getty on tty1. machine # [ 8.912157] systemd[1]: Reached target Login Prompts. machine # [ 9.122012] cfg80211: Loading compiled-in X.509 certificates for regulatory database machine # [ 9.145316] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' machine # [ 9.146596] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' machine # [ 9.149351] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2 machine # [ 9.152113] cfg80211: failed to load regulatory.db machine # [ 9.051298] postgresql-pre-start[671]: The files belonging to this database system will be owned by user "postgres". machine # [ 9.051657] postgresql-pre-start[671]: This user must also own the server process. machine # [ 9.206685] 8021q: adding VLAN 0 to HW filter on device eth0 machine # [ 9.056521] dhcpcd[647]: eth0: waiting for carrier machine # [ 9.057472] dhcpcd[647]: eth0: carrier acquired machine # [ 9.062852] postgresql-pre-start[671]: The database cluster will be initialized with locale "en_US.UTF-8". machine # [ 9.064451] postgresql-pre-start[671]: The default database encoding has accordingly been set to "UTF8". machine # [ 9.065920] postgresql-pre-start[671]: The default text search configuration will be set to "english". machine # [ 9.067452] postgresql-pre-start[671]: Data page checksums are enabled. machine # [ 9.068606] postgresql-pre-start[671]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok machine # [ 9.070592] postgresql-pre-start[671]: creating subdirectories ... ok machine # [ 9.072073] postgresql-pre-start[671]: selecting dynamic shared memory implementation ... posix machine # [ 9.073550] dhcpcd[647]: DUID 00:01:00:01:32:39:7a:c4:52:54:00:12:34:56 machine # [ 9.074728] dhcpcd[647]: eth0: IAID 00:12:34:56 machine # [ 9.075790] dhcpcd[647]: eth0: adding address fe80::5054:ff:fe12:3456 machine # [ 9.147454] postgresql-pre-start[671]: selecting default "max_connections" ... 100 machine # [ 9.206096] postgresql-pre-start[671]: selecting default "shared_buffers" ... 128MB machine # [ 9.237777] dhcpcd[647]: eth0: soliciting a DHCP lease machine # [ 9.404133] NET: Registered PF_PACKET protocol family machine # [ 9.258464] dhcpcd[647]: eth0: offered 10.0.2.15 from 10.0.2.2 machine # [ 9.266172] dhcpcd[647]: eth0: probing address 10.0.2.15/24 machine # [ 10.700856] dhcpcd[647]: eth0: soliciting an IPv6 router machine # [ 10.701759] dhcpcd[647]: eth0: Router Advertisement from fe80::2 machine # [ 10.702595] dhcpcd[647]: eth0: adding address fec0::5054:ff:fe12:3456/64 machine # [ 10.703666] dhcpcd[647]: eth0: adding route to fec0::/64 machine # [ 10.704864] dhcpcd[647]: eth0: adding default route via fe80::2 machine # [ 11.298298] postgresql-pre-start[671]: selecting default time zone ... UTC machine # [ 11.302577] postgresql-pre-start[671]: creating configuration files ... ok machine # [ 11.554587] postgresql-pre-start[671]: running bootstrap script ... ok machine # [ 12.110448] postgresql-pre-start[671]: performing post-bootstrap initialization ... ok machine # [ 12.269388] postgresql-pre-start[671]: syncing data to disk ... ok machine # [ 12.270399] postgresql-pre-start[671]: initdb: warning: enabling "trust" authentication for local connections machine # [ 12.272201] postgresql-pre-start[671]: initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb. machine # [ 12.275115] postgresql-pre-start[671]: Success. You can now start the database server using: machine # [ 12.276791] postgresql-pre-start[671]: pg_ctl -D /var/lib/postgresql/18 -l logfile start machine # [ 12.415180] postgres[732]: [732] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit machine # [ 12.417656] postgres[732]: [732] LOG: listening on IPv4 address "0.0.0.0", port 5432 machine # [ 12.418988] postgres[732]: [732] LOG: listening on IPv6 address "::", port 5432 machine # [ 12.421619] postgres[732]: [732] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432" machine # [ 12.437455] postgres[741]: [741] LOG: database system was shut down at 2026-09-13 15:16:24 GMT machine # [ 12.444401] postgres[732]: [732] LOG: database system is ready to accept connections machine # [ 12.450688] systemd[1]: Started PostgreSQL Server. machine # [ 12.455120] systemd[1]: Starting PostgreSQL Setup Scripts... machine # [ 12.690831] postgresql-setup-start[752]: CREATE DATABASE machine # [ 12.739346] postgresql-setup-start[757]: CREATE ROLE machine # [ 12.761351] postgresql-setup-start[759]: ALTER DATABASE machine # [ 12.765805] systemd[1]: Finished PostgreSQL Setup Scripts. machine # [ 12.767097] systemd[1]: Reached target PostgreSQL. machine # [ 14.154807] dhcpcd[647]: eth0: leased 10.0.2.15 for 86400 seconds machine # [ 14.157902] dhcpcd[647]: eth0: adding route to 10.0.2.0/24 machine # [ 14.160256] dhcpcd[647]: eth0: adding default route via 10.0.2.2 machine # [ 14.352624] systemd[1]: Started DHCP Client. machine # [ 14.354793] systemd[1]: Reached target Network is Online. machine # [ 14.360190] systemd[1]: Starting k3s service... machine # [ 14.532373] k3s[835]: time="2026-09-13T15:16:26Z" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock" machine # [ 14.532624] k3s[835]: time="2026-09-13T15:16:26Z" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/76c98da5fd74d9a243cba8d533ae287fc547ab08ccd8c5ea4811608ce7075724" machine # [ 18.082663] rustfs-setup-start[852]: mb s3://niks3 machine # [ 18.088563] systemd[1]: Finished rustfs-setup.service. machine # [ 18.605343] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Starting k3s 1.35.8+k3s1 (e952d68a)" machine # [ 18.613422] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Configuring sqlite3 database connection pooling: maxIdle=20, maxOpen=0, maxLifetime=0s, maxIdleTime=2m0s" machine # [ 18.616081] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Kine built with sqlite from github.com/mattn/go-sqlite3 version 3.53.3" machine # [ 18.616506] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Configuring database table schema and indexes, this may take a moment..." machine # [ 18.629545] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Database tables and indexes are up to date" machine # [ 18.631219] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Running startup VACUUM to reclaim disk space, this may take a moment..." machine # [ 18.634953] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Startup VACUUM completed successfully" machine # [ 18.637396] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Kine available at unix://kine.sock" machine # [ 18.638578] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]" machine # [ 18.640729] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Datastore connection validated successfully, proceeding with bootstrap data generation" machine # [ 18.642481] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="generated self-signed CA certificate CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:30.559208641 +0000 UTC notAfter=2036-09-10 14:16:30.559208641 +0000 UTC" machine # [ 18.644811] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.647236] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=system:k3s-supervisor,O=system:masters signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.649683] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.652077] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.654349] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=system:apiserver,O=system:masters signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.656735] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.659055] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="generated self-signed CA certificate CN=k3s-server-ca@1789312590: notBefore=2026-09-13 14:16:30.565931003 +0000 UTC notAfter=2036-09-10 14:16:30.565931003 +0000 UTC" machine # [ 18.661385] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.663592] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=kube-scheduler signed by CN=k3s-server-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.665768] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=kube-controller-manager signed by CN=k3s-server-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.667995] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="generated self-signed CA certificate CN=k3s-request-header-ca@1789312590: notBefore=2026-09-13 14:16:30.568862661 +0000 UTC notAfter=2036-09-10 14:16:30.568862661 +0000 UTC" machine # [ 18.670758] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.673197] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="generated self-signed CA certificate CN=etcd-server-ca@1789312590: notBefore=2026-09-13 14:16:30.569565544 +0000 UTC notAfter=2036-09-10 14:16:30.569565544 +0000 UTC" machine # [ 18.675753] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.678040] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="generated self-signed CA certificate CN=etcd-peer-ca@1789312590: notBefore=2026-09-13 14:16:30.570257252 +0000 UTC notAfter=2036-09-10 14:16:30.570257252 +0000 UTC" machine # [ 18.680698] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.682950] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.695692] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1789312590: notBefore=2026-09-13 14:16:30 +0000 UTC notAfter=2027-09-13 14:16:30 +0000 UTC" machine # [ 18.698023] k3s[835]: time="2026-09-13T15:16:30Z" level=warning msg="dynamiclistener [::]:6443: no cached certificate available for preload - deferring certificate load until storage initialization or first client request" machine # [ 18.704526] k3s[835]: time="2026-09-13T15:16:30Z" 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__5324_8bf6_15bd_aa25-fb21a3:fec0::5324:8bf6:15bd:aa25 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=B78C0C4A551049D30E2226F67AB84CEC4382D92F]" machine # [ 19.509302] k3s[835]: time="2026-09-13T15:16:31Z" level=info msg="Password verified locally for node machine" machine # [ 19.512729] k3s[835]: time="2026-09-13T15:16:31Z" level=info msg="certificate CN=machine signed by CN=k3s-server-ca@1789312590: notBefore=2026-09-13 14:16:31 +0000 UTC notAfter=2027-09-13 14:16:31 +0000 UTC" machine # [ 19.758736] k3s[835]: time="2026-09-13T15:16:31Z" level=info msg="certificate CN=system:node:machine,O=system:nodes signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:31 +0000 UTC notAfter=2027-09-13 14:16:31 +0000 UTC" machine # [ 19.854398] k3s[835]: time="2026-09-13T15:16:31Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:31 +0000 UTC notAfter=2027-09-13 14:16:31 +0000 UTC" machine # [ 19.927364] k3s[835]: time="2026-09-13T15:16:31Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1789312590: notBefore=2026-09-13 14:16:31 +0000 UTC notAfter=2027-09-13 14:16:31 +0000 UTC" machine # [ 20.000546] k3s[835]: time="2026-09-13T15:16:31Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:37592: runtime core not ready" machine # [ 20.074277] k3s[835]: time="2026-09-13T15:16:31Z" level=info msg="Module overlay was already loaded" machine # [ 20.327653] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this. machine # [ 20.333086] Bridge firewalling registered machine # [ 20.204215] k3s[835]: time="2026-09-13T15:16:32Z" level=warning msg="Failed to load kernel module iptable_nat with modprobe" machine # [ 20.227974] k3s[835]: time="2026-09-13T15:16:32Z" level=warning msg="Failed to load kernel module iptable_filter with modprobe" machine # [ 20.249472] k3s[835]: time="2026-09-13T15:16:32Z" level=warning msg="Failed to load kernel module nft-expr-counter with modprobe" machine # [ 20.344552] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Set sysctl 'net/ipv4/conf/all/forwarding' to 1" machine # [ 20.346698] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_max' to 131072" machine # [ 20.348764] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400" machine # [ 20.350531] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_close_wait' to 3600" machine # [ 20.352753] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Polling for API server readiness: GET /readyz failed: the server is currently unable to handle the request" machine # [ 20.354976] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Connecting to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 20.356941] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Handling backend connection request [machine]" machine # [ 20.358574] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Creating k3s-cert-monitor event broadcaster" machine # [ 20.359863] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Saving cluster bootstrap data to datastore" machine # [ 20.361201] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 20.363111] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Remotedialer connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 20.364745] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]" machine # [ 20.366912] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Connection to etcd is ready" machine # [ 20.368306] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="ETCD server is now running" machine # [ 20.369860] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=https://kubernetes.default.svc.cluster.local,k3s --authorization-mode=Node,RBAC --bind-address=127.0.0.1 --cert-dir=/var/lib/rancher/k3s/server/tls/temporary-certs --client-ca-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --egress-selector-config-file=/var/lib/rancher/k3s/server/etc/egress-selector-config.yaml --enable-admission-plugins=NodeRestriction --enable-aggregator-routing=true --enable-bootstrap-token-auth=true --etcd-servers=unix://kine.sock --kubelet-certificate-authority=/var/lib/rancher/k3s/server/tls/server-ca.crt --kubelet-client-certificate=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.crt --kubelet-client-key=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.key --kubelet-preferred-address-types=InternalIP,ExternalIP,Hostname --profiling=false --proxy-client-cert-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt --proxy-client-key-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.key --requestheader-allowed-names=system:auth-proxy --requestheader-client-ca-file=/var/lib/rancher/k3s/server/tls/request-header-ca.crt --requestheader-extra-headers-prefix=X-Remote-Extra- --requestheader-group-headers=X-Remote-Group --requestheader-username-headers=X-Remote-User --secure-port=6444 --service-account-issuer=https://kubernetes.default.svc.cluster.local --service-account-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-account-signing-key-file=/var/lib/rancher/k3s/server/tls/service.current.key --service-cluster-ip-range=10.43.0.0/16 --service-node-port-range=30000-32767 --storage-backend=etcd3 --tls-cert-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt --tls-cipher-suites=TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305,TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305 --tls-private-key-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key" machine # [ 20.394925] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Running kube-scheduler --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --bind-address=127.0.0.1 --kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --leader-elect=false --profiling=false --secure-port=10259 --tls-cert-file=/var/lib/rancher/k3s/server/tls/kube-scheduler/kube-scheduler.crt --tls-private-key-file=/var/lib/rancher/k3s/server/tls/kube-scheduler/kube-scheduler.key" machine # [ 20.402594] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Running kube-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --bind-address=127.0.0.1 --cluster-cidr=10.42.0.0/16 --cluster-signing-kube-apiserver-client-cert-file=/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt --cluster-signing-kube-apiserver-client-key-file=/var/lib/rancher/k3s/server/tls/client-ca.key --cluster-signing-kubelet-client-cert-file=/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt --cluster-signing-kubelet-client-key-file=/var/lib/rancher/k3s/server/tls/client-ca.key --cluster-signing-kubelet-serving-cert-file=/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt --cluster-signing-kubelet-serving-key-file=/var/lib/rancher/k3s/server/tls/server-ca.key --cluster-signing-legacy-unknown-cert-file=/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt --cluster-signing-legacy-unknown-key-file=/var/lib/rancher/k3s/server/tls/server-ca.key --configure-cloud-routes=false --controllers=*,tokencleaner,-service,-route,-cloud-node-lifecycle --kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --leader-elect=false --profiling=false --root-ca-file=/var/lib/rancher/k3s/server/tls/server-ca.crt --secure-port=10257 --service-account-private-key-file=/var/lib/rancher/k3s/server/tls/service.current.key --service-cluster-ip-range=10.43.0.0/16 --tls-cert-file=/var/lib/rancher/k3s/server/tls/kube-controller-manager/kube-controller-manager.crt --tls-private-key-file=/var/lib/rancher/k3s/server/tls/kube-controller-manager/kube-controller-manager.key --use-service-account-credentials=true" machine # [ 20.422052] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Running cloud-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --bind-address=127.0.0.1 --cloud-config=/var/lib/rancher/k3s/server/etc/cloud-config.yaml --cloud-provider=k3s --cluster-cidr=10.42.0.0/16 --configure-cloud-routes=false --controllers=*,-route --kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --leader-elect=false --leader-elect-resource-name=k3s-cloud-controller-manager --node-status-update-frequency=1m0s --profiling=false" machine # [ 20.432275] k3s[835]: I0913 15:16:32.289450 835 options.go:263] external host was not specified, using 10.0.2.15 machine # [ 20.433596] k3s[835]: I0913 15:16:32.295599 835 server.go:158] Version: v1.35.8+k3s1 machine # [ 20.434847] k3s[835]: I0913 15:16:32.295769 835 server.go:160] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 20.436363] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token" machine # [ 20.437906] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="To join server node to cluster: k3s server -s https://10.0.2.15:6443 -t ${SERVER_NODE_TOKEN}" machine # [ 20.440507] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token" machine # [ 20.442542] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="To join agent node to cluster: k3s agent -s https://10.0.2.15:6443 -t ${AGENT_NODE_TOKEN}" machine # [ 20.444299] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml" machine # [ 20.446069] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Run: k3s kubectl" machine # [ 20.460716] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log" machine # [ 20.473611] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml" machine # [ 20.475158] k3s[835]: time="2026-09-13T15:16:32Z" level=error msg="Sending HTTP/1.1 503 response to 127.0.0.1:37636: runtime core not ready" machine # [ 20.585097] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Running kube-proxy --cluster-cidr=10.42.0.0/16 --conntrack-max-per-core=0 --conntrack-tcp-timeout-close-wait=0s --conntrack-tcp-timeout-established=0s --healthz-bind-address=127.0.0.1 --hostname-override=machine --kubeconfig=/var/lib/rancher/k3s/agent/kubeproxy.kubeconfig --proxy-mode=iptables" machine # [ 20.604602] k3s[835]: I0913 15:16:32.522680 835 shared_informer.go:349] "Waiting for caches to sync" controller="node_authorizer" machine # [ 20.608370] k3s[835]: I0913 15:16:32.526445 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 20.611405] k3s[835]: I0913 15:16:32.529499 835 plugins.go:157] Loaded 14 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,RuntimeClass,DefaultIngressClass,PodTopologyLabels,MutatingAdmissionPolicy,MutatingAdmissionWebhook. machine # [ 20.615530] k3s[835]: I0913 15:16:32.533631 835 plugins.go:160] Loaded 14 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,PodSecurity,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,ClusterTrustBundleAttest,CertificateSubjectRestriction,NodeDeclaredFeatureValidator,ValidatingAdmissionPolicy,ValidatingAdmissionWebhook,ResourceQuota. machine # [ 20.623202] k3s[835]: I0913 15:16:32.538188 835 instance.go:240] Using reconciler: lease machine # [ 20.627796] k3s[835]: I0913 15:16:32.545789 835 handler.go:304] Adding GroupVersion apiextensions.k8s.io v1 to ResourceManager machine # [ 20.629277] k3s[835]: W0913 15:16:32.545820 835 genericapiserver.go:787] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources. machine # [ 20.632696] k3s[835]: I0913 15:16:32.550790 835 cidrallocator.go:198] starting ServiceCIDR Allocator Controller machine # [ 20.673621] k3s[835]: I0913 15:16:32.591595 835 handler.go:304] Adding GroupVersion v1 to ResourceManager machine # [ 20.675305] k3s[835]: I0913 15:16:32.591749 835 apis.go:112] API group "internal.apiserver.k8s.io" is not enabled, skipping. machine # [ 20.709948] k3s[835]: I0913 15:16:32.627980 835 apis.go:112] API group "storagemigration.k8s.io" is not enabled, skipping. machine # [ 20.763747] k3s[835]: I0913 15:16:32.681509 835 handler.go:304] Adding GroupVersion authentication.k8s.io v1 to ResourceManager machine # [ 20.765468] k3s[835]: W0913 15:16:32.683569 835 genericapiserver.go:787] Skipping API authentication.k8s.io/v1beta1 because it has no resources. machine # [ 20.769231] k3s[835]: W0913 15:16:32.685671 835 genericapiserver.go:787] Skipping API authentication.k8s.io/v1alpha1 because it has no resources. machine # [ 20.771474] k3s[835]: I0913 15:16:32.685995 835 handler.go:304] Adding GroupVersion authorization.k8s.io v1 to ResourceManager machine # [ 20.773116] k3s[835]: W0913 15:16:32.686010 835 genericapiserver.go:787] Skipping API authorization.k8s.io/v1beta1 because it has no resources. machine # [ 20.775406] k3s[835]: I0913 15:16:32.686568 835 handler.go:304] Adding GroupVersion autoscaling v2 to ResourceManager machine # [ 20.777254] k3s[835]: I0913 15:16:32.687006 835 handler.go:304] Adding GroupVersion autoscaling v1 to ResourceManager machine # [ 20.779122] k3s[835]: W0913 15:16:32.687020 835 genericapiserver.go:787] Skipping API autoscaling/v2beta1 because it has no resources. machine # [ 20.780791] k3s[835]: W0913 15:16:32.687030 835 genericapiserver.go:787] Skipping API autoscaling/v2beta2 because it has no resources. machine # [ 20.782994] k3s[835]: I0913 15:16:32.690998 835 handler.go:304] Adding GroupVersion batch v1 to ResourceManager machine # [ 20.784834] k3s[835]: W0913 15:16:32.691026 835 genericapiserver.go:787] Skipping API batch/v1beta1 because it has no resources. machine # [ 20.786713] k3s[835]: I0913 15:16:32.691695 835 handler.go:304] Adding GroupVersion certificates.k8s.io v1 to ResourceManager machine # [ 20.788566] k3s[835]: W0913 15:16:32.691712 835 genericapiserver.go:787] Skipping API certificates.k8s.io/v1beta1 because it has no resources. machine # [ 20.790191] k3s[835]: W0913 15:16:32.691724 835 genericapiserver.go:787] Skipping API certificates.k8s.io/v1alpha1 because it has no resources. machine # [ 20.791775] k3s[835]: I0913 15:16:32.692062 835 handler.go:304] Adding GroupVersion coordination.k8s.io v1 to ResourceManager machine # [ 20.793254] k3s[835]: W0913 15:16:32.692078 835 genericapiserver.go:787] Skipping API coordination.k8s.io/v1beta1 because it has no resources. machine # [ 20.795489] k3s[835]: W0913 15:16:32.692088 835 genericapiserver.go:787] Skipping API coordination.k8s.io/v1alpha2 because it has no resources. machine # [ 20.797686] k3s[835]: I0913 15:16:32.692517 835 handler.go:304] Adding GroupVersion discovery.k8s.io v1 to ResourceManager machine # [ 20.799718] k3s[835]: W0913 15:16:32.692535 835 genericapiserver.go:787] Skipping API discovery.k8s.io/v1beta1 because it has no resources. machine # [ 20.801918] k3s[835]: I0913 15:16:32.694085 835 handler.go:304] Adding GroupVersion networking.k8s.io v1 to ResourceManager machine # [ 20.803894] k3s[835]: W0913 15:16:32.694102 835 genericapiserver.go:787] Skipping API networking.k8s.io/v1beta1 because it has no resources. machine # [ 20.806174] k3s[835]: I0913 15:16:32.694519 835 handler.go:304] Adding GroupVersion node.k8s.io v1 to ResourceManager machine # [ 20.807988] k3s[835]: W0913 15:16:32.694535 835 genericapiserver.go:787] Skipping API node.k8s.io/v1beta1 because it has no resources. machine # [ 20.809848] k3s[835]: W0913 15:16:32.694546 835 genericapiserver.go:787] Skipping API node.k8s.io/v1alpha1 because it has no resources. machine # [ 20.811399] k3s[835]: I0913 15:16:32.695232 835 handler.go:304] Adding GroupVersion policy v1 to ResourceManager machine # [ 20.813073] k3s[835]: W0913 15:16:32.695249 835 genericapiserver.go:787] Skipping API policy/v1beta1 because it has no resources. machine # [ 20.814806] k3s[835]: I0913 15:16:32.696558 835 handler.go:304] Adding GroupVersion rbac.authorization.k8s.io v1 to ResourceManager machine # [ 20.816973] k3s[835]: W0913 15:16:32.696576 835 genericapiserver.go:787] Skipping API rbac.authorization.k8s.io/v1beta1 because it has no resources. machine # [ 20.819141] k3s[835]: W0913 15:16:32.696587 835 genericapiserver.go:787] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources. machine # [ 20.820732] k3s[835]: I0913 15:16:32.696908 835 handler.go:304] Adding GroupVersion scheduling.k8s.io v1 to ResourceManager machine # [ 20.822146] k3s[835]: W0913 15:16:32.696923 835 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1beta1 because it has no resources. machine # [ 20.824396] k3s[835]: W0913 15:16:32.696934 835 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources. machine # [ 20.826478] k3s[835]: I0913 15:16:32.698383 835 handler.go:304] Adding GroupVersion storage.k8s.io v1 to ResourceManager machine # [ 20.828443] k3s[835]: W0913 15:16:32.698536 835 genericapiserver.go:787] Skipping API storage.k8s.io/v1beta1 because it has no resources. machine # [ 20.830605] k3s[835]: W0913 15:16:32.698549 835 genericapiserver.go:787] Skipping API storage.k8s.io/v1alpha1 because it has no resources. machine # [ 20.832387] k3s[835]: I0913 15:16:32.699332 835 handler.go:304] Adding GroupVersion flowcontrol.apiserver.k8s.io v1 to ResourceManager machine # [ 20.833797] k3s[835]: W0913 15:16:32.699349 835 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta3 because it has no resources. machine # [ 20.836112] k3s[835]: W0913 15:16:32.699360 835 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta2 because it has no resources. machine # [ 20.838545] k3s[835]: W0913 15:16:32.699370 835 genericapiserver.go:787] Skipping API flowcontrol.apiserver.k8s.io/v1beta1 because it has no resources. machine # [ 20.840842] k3s[835]: I0913 15:16:32.702123 835 handler.go:304] Adding GroupVersion apps v1 to ResourceManager machine # [ 20.842550] k3s[835]: W0913 15:16:32.702232 835 genericapiserver.go:787] Skipping API apps/v1beta2 because it has no resources. machine # [ 20.844604] k3s[835]: W0913 15:16:32.702245 835 genericapiserver.go:787] Skipping API apps/v1beta1 because it has no resources. machine # [ 20.846072] k3s[835]: I0913 15:16:32.703526 835 handler.go:304] Adding GroupVersion admissionregistration.k8s.io v1 to ResourceManager machine # [ 20.847658] k3s[835]: W0913 15:16:32.703545 835 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources. machine # [ 20.849727] k3s[835]: W0913 15:16:32.703556 835 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources. machine # [ 20.852119] k3s[835]: I0913 15:16:32.703939 835 handler.go:304] Adding GroupVersion events.k8s.io v1 to ResourceManager machine # [ 20.854178] k3s[835]: W0913 15:16:32.703956 835 genericapiserver.go:787] Skipping API events.k8s.io/v1beta1 because it has no resources. machine # [ 20.856366] k3s[835]: I0913 15:16:32.705360 835 handler.go:304] Adding GroupVersion resource.k8s.io v1 to ResourceManager machine # [ 20.858332] k3s[835]: W0913 15:16:32.705378 835 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta2 because it has no resources. machine # [ 20.860094] k3s[835]: W0913 15:16:32.705389 835 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta1 because it has no resources. machine # [ 20.861639] k3s[835]: W0913 15:16:32.705398 835 genericapiserver.go:787] Skipping API resource.k8s.io/v1alpha3 because it has no resources. machine # [ 20.863585] k3s[835]: I0913 15:16:32.707669 835 handler.go:304] Adding GroupVersion apiregistration.k8s.io v1 to ResourceManager machine # [ 20.865738] k3s[835]: W0913 15:16:32.707688 835 genericapiserver.go:787] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources. machine # [ 21.191986] k3s[835]: I0913 15:16:33.108765 835 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt" machine # [ 21.194024] k3s[835]: I0913 15:16:33.108923 835 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt" machine # [ 21.195935] k3s[835]: I0913 15:16:33.108984 835 secure_serving.go:211] Serving securely on 127.0.0.1:6444 machine # [ 21.197121] k3s[835]: I0913 15:16:33.109100 835 apf_controller.go:377] Starting API Priority and Fairness config controller machine # [ 21.198567] k3s[835]: I0913 15:16:33.109176 835 dynamic_serving_content.go:135] "Starting controller" name="aggregator-proxy-cert::/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt::/var/lib/rancher/k3s/server/tls/client-auth-proxy.key" machine # [ 21.200968] k3s[835]: I0913 15:16:33.109581 835 dynamic_serving_content.go:135] "Starting controller" name="serving-cert::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key" machine # [ 21.203516] k3s[835]: I0913 15:16:33.109677 835 local_available_controller.go:156] Starting LocalAvailability controller machine # [ 21.204833] k3s[835]: I0913 15:16:33.109681 835 tlsconfig.go:243] "Starting DynamicServingCertificateController" machine # [ 21.206112] k3s[835]: I0913 15:16:33.109692 835 cache.go:32] Waiting for caches to sync for LocalAvailability controller machine # [ 21.207463] k3s[835]: I0913 15:16:33.109740 835 controller.go:80] Starting OpenAPI V3 AggregationController machine # [ 21.208670] k3s[835]: I0913 15:16:33.109930 835 customresource_discovery_controller.go:294] Starting DiscoveryController machine # [ 21.210061] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Starting apiserver lease garbage collector" logger=k3s machine # [ 21.211365] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Waiting for caches to sync" logger=k3s machine # [ 21.212483] k3s[835]: I0913 15:16:33.110079 835 aggregator.go:185] waiting for initial CRD sync... machine # [ 21.213693] k3s[835]: I0913 15:16:33.110101 835 controller.go:78] Starting OpenAPI AggregationController machine # [ 21.214959] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Starting legacy_token_tracking_controller" logger=k3s machine # [ 21.216204] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Waiting for caches to sync" logger=k3s machine # [ 21.217393] k3s[835]: I0913 15:16:33.110634 835 system_namespaces_controller.go:66] Starting system namespaces controller machine # [ 21.218712] k3s[835]: I0913 15:16:33.110863 835 controller.go:142] Starting OpenAPI controller machine # [ 21.219837] k3s[835]: I0913 15:16:33.110930 835 controller.go:90] Starting OpenAPI V3 controller machine # [ 21.220914] k3s[835]: I0913 15:16:33.110962 835 naming_controller.go:305] Starting NamingConditionController machine # [ 21.222171] k3s[835]: I0913 15:16:33.111030 835 nonstructuralschema_controller.go:202] Starting NonStructuralSchemaConditionController machine # [ 21.223628] k3s[835]: I0913 15:16:33.111064 835 apiapproval_controller.go:196] Starting KubernetesAPIApprovalPolicyConformantConditionController machine # [ 21.225184] k3s[835]: I0913 15:16:33.111093 835 crd_finalizer.go:273] Starting CRDFinalizer machine # [ 21.226364] k3s[835]: I0913 15:16:33.111190 835 repairip.go:210] Starting ipallocator-repair-controller machine # [ 21.227511] k3s[835]: I0913 15:16:33.111203 835 shared_informer.go:349] "Waiting for caches to sync" controller="ipallocator-repair-controller" machine # [ 21.229061] k3s[835]: I0913 15:16:33.111500 835 crdregistration_controller.go:114] Starting crd-autoregister controller machine # [ 21.230446] k3s[835]: I0913 15:16:33.111514 835 shared_informer.go:349] "Waiting for caches to sync" controller="crd-autoregister" machine # [ 21.231841] k3s[835]: I0913 15:16:33.111579 835 default_servicecidr_controller.go:110] Starting kubernetes-service-cidr-controller machine # [ 21.233239] k3s[835]: I0913 15:16:33.111595 835 shared_informer.go:349] "Waiting for caches to sync" controller="kubernetes-service-cidr-controller" machine # [ 21.234897] k3s[835]: I0913 15:16:33.112935 835 cluster_authentication_trust_controller.go:459] Starting cluster_authentication_trust_controller controller machine # [ 21.236551] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Waiting for caches to sync" logger=k3s machine # [ 21.237773] k3s[835]: I0913 15:16:33.113034 835 controller.go:113] "Deleting old lease on startup" lease="kube-system/apiserver-ik4pcwfs7qgdl76byc4pomgvia" machine # [ 21.239457] k3s[835]: I0913 15:16:33.113243 835 remote_available_controller.go:425] Starting RemoteAvailability controller machine # [ 21.240838] k3s[835]: I0913 15:16:33.113255 835 cache.go:32] Waiting for caches to sync for RemoteAvailability controller machine # [ 21.242143] k3s[835]: I0913 15:16:33.113298 835 apiservice_controller.go:100] Starting APIServiceRegistrationController machine # [ 21.243547] k3s[835]: I0913 15:16:33.113308 835 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller machine # [ 21.245085] k3s[835]: I0913 15:16:33.116087 835 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt" machine # [ 21.246891] k3s[835]: I0913 15:16:33.116187 835 dynamic_cafile_content.go:161] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt" machine # [ 21.291704] k3s[835]: I0913 15:16:33.209749 835 cache.go:39] Caches are synced for LocalAvailability controller machine # [ 21.293112] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Caches are synced" logger=k3s machine # [ 21.296053] k3s[835]: I0913 15:16:33.212650 835 shared_informer.go:356] "Caches are synced" controller="kubernetes-service-cidr-controller" machine # [ 21.297643] k3s[835]: I0913 15:16:33.212693 835 default_servicecidr_controller.go:169] Creating default ServiceCIDR with CIDRs: [10.43.0.0/16] machine # [ 21.299156] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Caches are synced" logger=k3s machine # [ 21.300191] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Caches are synced" logger=k3s machine # [ 21.301316] k3s[835]: I0913 15:16:33.213309 835 cache.go:39] Caches are synced for RemoteAvailability controller machine # [ 21.302545] k3s[835]: I0913 15:16:33.213350 835 cache.go:39] Caches are synced for APIServiceRegistrationController controller machine # [ 21.303964] k3s[835]: I0913 15:16:33.213616 835 shared_informer.go:356] "Caches are synced" controller="ipallocator-repair-controller" machine # [ 21.305486] k3s[835]: I0913 15:16:33.213654 835 shared_informer.go:356] "Caches are synced" controller="crd-autoregister" machine # [ 21.306831] k3s[835]: I0913 15:16:33.216237 835 handler_discovery.go:451] Starting ResourceDiscoveryManager machine # [ 21.308064] k3s[835]: I0913 15:16:33.216384 835 aggregator.go:187] initial CRD sync complete... machine # [ 21.309173] k3s[835]: I0913 15:16:33.216396 835 autoregister_controller.go:144] Starting autoregister controller machine # [ 21.310500] k3s[835]: I0913 15:16:33.216407 835 cache.go:32] Waiting for caches to sync for autoregister controller machine # [ 21.311771] k3s[835]: I0913 15:16:33.216418 835 cache.go:39] Caches are synced for autoregister controller machine # [ 21.313018] k3s[835]: I0913 15:16:33.224588 835 shared_informer.go:356] "Caches are synced" controller="node_authorizer" machine # [ 21.314407] k3s[835]: I0913 15:16:33.227204 835 shared_informer.go:377] "Caches are synced" machine # [ 21.315453] k3s[835]: I0913 15:16:33.227231 835 policy_source.go:248] refreshing policies machine # [ 21.349233] k3s[835]: E0913 15:16:33.267280 835 controller.go:201] "Failed to ensure lease exists, will retry" err="namespaces \"kube-system\" not found" interval="200ms" machine # [ 21.351178] k3s[835]: E0913 15:16:33.267349 835 controller.go:95] Unable to perform initial Kubernetes service initialization: namespaces "default" not found machine # [ 21.355158] k3s[835]: time="2026-09-13T15:16:33Z" level=error msg="Error while syncing ConfigMap" configmap=kube-system/kube-apiserver-legacy-service-account-token-tracking error="namespaces \"kube-system\" not found" logger=k3s/UnhandledError machine # [ 21.392377] k3s[835]: I0913 15:16:33.310258 835 apf_controller.go:382] Running API Priority and Fairness config worker machine # [ 21.393283] k3s[835]: I0913 15:16:33.310312 835 apf_controller.go:385] Running API Priority and Fairness periodic rebalancing process machine # [ 21.401248] k3s[835]: I0913 15:16:33.319244 835 controller.go:667] quota admission added evaluator for: namespaces machine # [ 21.414068] k3s[835]: I0913 15:16:33.330628 835 cidrallocator.go:302] created ClusterIP allocator for Service CIDR 10.43.0.0/16 machine # [ 21.416127] k3s[835]: I0913 15:16:33.334204 835 default_servicecidr_controller.go:231] Setting default ServiceCIDR condition Ready to True machine # [ 21.425643] k3s[835]: I0913 15:16:33.343726 835 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/16 machine # [ 21.432079] k3s[835]: I0913 15:16:33.350130 835 default_servicecidr_controller.go:231] Setting default ServiceCIDR condition Ready to True machine # [ 21.502370] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="containerd is now running" machine # [ 21.515426] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/k3s-airgap-images-amd64.tar.zst" machine # [ 21.565429] k3s[835]: I0913 15:16:33.483477 835 controller.go:667] quota admission added evaluator for: leases.coordination.k8s.io machine # [ 22.202088] k3s[835]: I0913 15:16:34.119811 835 storage_scheduling.go:123] created PriorityClass system-node-critical with value 2000001000 machine # [ 22.210169] k3s[835]: I0913 15:16:34.128249 835 storage_scheduling.go:123] created PriorityClass system-cluster-critical with value 2000000000 machine # [ 22.211791] k3s[835]: I0913 15:16:34.128277 835 storage_scheduling.go:139] all system priority classes are created successfully or already exist. machine # [ 22.351109] k3s[835]: time="2026-09-13T15:16:34Z" level=info msg="Polling for API server readiness: GET /readyz failed: unknown" machine # [ 23.279917] k3s[835]: I0913 15:16:35.197672 835 controller.go:667] quota admission added evaluator for: roles.rbac.authorization.k8s.io machine # [ 23.320507] k3s[835]: I0913 15:16:35.238556 835 controller.go:667] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io machine # [ 23.460700] k3s[835]: I0913 15:16:35.378680 835 alloc.go:329] "allocated clusterIPs" service="default/kubernetes" clusterIPs={"IPv4":"10.43.0.1"} machine # [ 23.467381] k3s[835]: W0913 15:16:35.385293 835 lease.go:265] Resetting endpoints for master service "kubernetes" to [10.0.2.15] machine # [ 23.472909] k3s[835]: I0913 15:16:35.390798 835 controller.go:667] quota admission added evaluator for: endpoints machine # [ 23.478056] k3s[835]: I0913 15:16:35.396122 835 controller.go:667] quota admission added evaluator for: endpointslices.discovery.k8s.io machine # [ 24.358382] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating k3s-supervisor event broadcaster" machine # [ 24.366431] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Waiting for untainted node" machine # [ 24.367667] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Kube API server is now running" machine # [ 24.368830] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="k3s is up and running" machine # [ 24.369864] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Node and Certificate Authority certificates managed by k3s are OK" object=machine reason=CertificateExpirationOK type=Normal machine # [ 24.377316] systemd[1]: Started k3s service. machine # [ 24.377989] systemd[1]: Reached target Multi-User System. machine # [ 24.378802] systemd[1]: Startup finished in 971ms (kernel) + 3.947s (initrd) + 19.453s (userspace) = 24.372s. machine # [ 24.409679] k3s[835]: I0913 15:16:36.327645 835 controllermanager.go:189] "Starting" version="v1.35.8+k3s1" machine # [ 24.411153] k3s[835]: I0913 15:16:36.327671 835 controllermanager.go:191] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 24.421662] k3s[835]: I0913 15:16:36.339570 835 secure_serving.go:211] Serving securely on 127.0.0.1:10257 machine # [ 24.423722] k3s[835]: I0913 15:16:36.340164 835 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController machine # [ 24.425201] k3s[835]: I0913 15:16:36.340184 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 24.426406] k3s[835]: I0913 15:16:36.340224 835 dynamic_serving_content.go:135] "Starting controller" name="serving-cert::/var/lib/rancher/k3s/server/tls/kube-controller-manager/kube-controller-manager.crt::/var/lib/rancher/k3s/server/tls/kube-controller-manager/kube-controller-manager.key" machine # [ 24.429338] k3s[835]: I0913 15:16:36.340314 835 tlsconfig.go:243] "Starting DynamicServingCertificateController" machine # [ 24.430981] k3s[835]: I0913 15:16:36.340382 835 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 24.433369] k3s[835]: I0913 15:16:36.340397 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 24.434896] k3s[835]: I0913 15:16:36.340427 835 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 24.437595] k3s[835]: I0913 15:16:36.340440 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 24.438839] k3s[835]: I0913 15:16:36.355439 835 controllermanager.go:627] "Warning: controller is disabled" controller="selinux-warning-controller" machine # [ 24.449560] k3s[835]: I0913 15:16:36.367605 835 controller.go:667] quota admission added evaluator for: serviceaccounts machine # [ 24.474246] k3s[835]: I0913 15:16:36.392253 835 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="podcertificaterequest-cleaner-controller" requiredFeatureGates=["PodCertificateRequest"] machine # [ 24.476706] k3s[835]: I0913 15:16:36.392304 835 controllermanager.go:579] "Warning: skipping controller" controller="podcertificaterequest-cleaner-controller" machine # [ 24.518797] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating embedded CRD addons.k3s.cattle.io" machine # [ 24.525026] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating embedded CRD etcdsnapshotfiles.k3s.cattle.io" machine # [ 24.526592] k3s[835]: I0913 15:16:36.444671 835 shared_informer.go:377] "Caches are synced" machine # [ 24.528497] k3s[835]: I0913 15:16:36.446578 835 shared_informer.go:377] "Caches are synced" machine # [ 24.529796] k3s[835]: I0913 15:16:36.446651 835 shared_informer.go:377] "Caches are synced" machine # [ 24.536551] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating embedded CRD helmchartconfigs.helm.cattle.io" machine # [ 24.553074] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating embedded CRD helmcharts.helm.cattle.io" machine # [ 24.557200] k3s[835]: I0913 15:16:36.475005 835 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="device-taint-eviction-controller" requiredFeatureGates=["DynamicResourceAllocation","DRADeviceTaints"] machine # [ 24.559640] k3s[835]: I0913 15:16:36.475025 835 controllermanager.go:579] "Warning: skipping controller" controller="device-taint-eviction-controller" machine # [ 24.562034] k3s[835]: I0913 15:16:36.475037 835 controllermanager.go:579] "Warning: skipping controller" controller="storage-version-migrator-controller" machine # [ 24.568735] k3s[835]: I0913 15:16:36.486800 835 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager machine # [ 24.585051] k3s[835]: I0913 15:16:36.503096 835 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager machine # [ 24.587286] k3s[835]: I0913 15:16:36.503730 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 24.590188] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Waiting for CRD helmchartconfigs.helm.cattle.io to become available" machine # [ 24.599319] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Done waiting for CRD helmchartconfigs.helm.cattle.io to become available" machine # [ 24.600880] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available" machine # [ 24.602646] k3s[835]: I0913 15:16:36.518244 835 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager machine # [ 24.614884] k3s[835]: I0913 15:16:36.532606 835 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager machine # [ 24.644913] k3s[835]: I0913 15:16:36.562801 835 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="storageversion-garbage-collector-controller" requiredFeatureGates=["APIServerIdentity","StorageVersionAPI"] machine # [ 24.647810] k3s[835]: I0913 15:16:36.562826 835 controllermanager.go:579] "Warning: skipping controller" controller="storageversion-garbage-collector-controller" machine: (finished: waiting for unit k3s.service, in 25.56 seconds) machine: waiting for unit rustfs-setup.service machine: (finished: waiting for unit rustfs-setup.service, in 0.08 seconds) machine: waiting for unit postgresql.service machine # [ 24.886543] k3s[835]: I0913 15:16:36.804498 835 shared_informer.go:377] "Caches are synced" machine: (finished: waiting for unit postgresql.service, in 0.12 seconds) subtest: chart deploys and becomes ready ??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/wqwvv2w9ih8r1f0lsa0h3fqf91nblq7g-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39 machine: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s ??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/wqwvv2w9ih8r1f0lsa0h3fqf91nblq7g-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39 machine # [ 25.119478] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available" machine # [ 25.121477] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-40.1.4+up40.1.0.tgz" machine # [ 25.123365] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-40.1.4+up40.1.0.tgz" machine # [ 25.126264] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml" machine # [ 25.129668] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml" machine # [ 25.131450] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml" machine # [ 25.133221] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml" machine # [ 25.134898] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/runtimes.yaml" machine # [ 25.136580] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml" machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 25.240737] k3s[835]: I0913 15:16:37.158712 835 controllermanager.go:627] "Warning: controller is disabled" controller="bootstrap-signer-controller" machine # [ 25.392398] k3s[835]: I0913 15:16:37.310094 835 node_lifecycle_controller.go:419] "Controller will reconcile labels" logger="node-lifecycle-controller" machine # [ 25.392721] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Starting dynamiclistener CN filter node controller with SANs: [127.0.0.1 ::1 localhost machine 10.0.2.15 fec0::5324:8bf6:15bd:aa25 10.43.0.1 kubernetes kubernetes.default kubernetes.default.svc kubernetes.default.svc.cluster.local]" machine # [ 25.393451] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Tunnel server egress proxy mode: agent" machine # [ 25.699142] k3s[835]: time="2026-09-13T15:16:37Z" 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__5324_8bf6_15bd_aa25-fb21a3:fec0::5324:8bf6:15bd:aa25 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=B78C0C4A551049D30E2226F67AB84CEC4382D92F]" machine # [ 25.719550] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Active TLS secret kube-system/k3s-serving (ver=235) (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__5324_8bf6_15bd_aa25-fb21a3:fec0::5324:8bf6:15bd:aa25 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=B78C0C4A551049D30E2226F67AB84CEC4382D92F]" machine # [ 25.845087] k3s[835]: W0913 15:16:37.763102 835 probe.go:272] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating. machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 26.647258] k3s[835]: I0913 15:16:38.564370 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="serviceaccounts" machine # [ 26.649430] k3s[835]: I0913 15:16:38.564429 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="limitranges" machine # [ 26.651564] k3s[835]: I0913 15:16:38.564460 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="controllerrevisions.apps" machine # [ 26.653812] k3s[835]: I0913 15:16:38.564497 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="ingresses.networking.k8s.io" machine # [ 26.656349] k3s[835]: I0913 15:16:38.564525 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="leases.coordination.k8s.io" machine # [ 26.659199] k3s[835]: I0913 15:16:38.564590 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="deployments.apps" machine # [ 26.661771] k3s[835]: I0913 15:16:38.564631 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="jobs.batch" machine # [ 26.664184] k3s[835]: I0913 15:16:38.564662 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="daemonsets.apps" machine # [ 26.666684] k3s[835]: I0913 15:16:38.564690 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpointslices.discovery.k8s.io" machine # [ 26.669545] k3s[835]: I0913 15:16:38.564724 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="resourceclaimtemplates.resource.k8s.io" machine # [ 26.672677] k3s[835]: I0913 15:16:38.564753 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="endpoints" machine # [ 26.675450] k3s[835]: I0913 15:16:38.564815 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="podtemplates" machine # [ 26.678200] k3s[835]: I0913 15:16:38.564886 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="networkpolicies.networking.k8s.io" machine # [ 26.681501] k3s[835]: I0913 15:16:38.564976 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="roles.rbac.authorization.k8s.io" machine # [ 26.681777] k3s[835]: I0913 15:16:38.565021 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmcharts.helm.cattle.io" machine # [ 26.682375] k3s[835]: I0913 15:16:38.565063 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="helmchartconfigs.helm.cattle.io" machine # [ 26.682834] k3s[835]: I0913 15:16:38.565114 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="cronjobs.batch" machine # [ 26.683298] k3s[835]: I0913 15:16:38.565218 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="poddisruptionbudgets.policy" machine # [ 26.683732] k3s[835]: I0913 15:16:38.565263 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="horizontalpodautoscalers.autoscaling" machine # [ 26.684368] k3s[835]: I0913 15:16:38.565302 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="csistoragecapacities.storage.k8s.io" machine # [ 26.684793] k3s[835]: I0913 15:16:38.565367 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="addons.k3s.cattle.io" machine # [ 26.685404] k3s[835]: I0913 15:16:38.565398 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="replicasets.apps" machine # [ 26.685833] k3s[835]: I0913 15:16:38.565489 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="statefulsets.apps" machine # [ 26.686429] k3s[835]: I0913 15:16:38.565545 835 resource_quota_monitor.go:229] "QuotaMonitor created object count evaluator" logger="resourcequota-controller" resource="rolebindings.rbac.authorization.k8s.io" machine # [ 26.702451] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller" machine # [ 26.702635] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Creating deploy event broadcaster" machine # [ 26.709047] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Starting /v1, Kind=Node controller" machine # [ 26.711054] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Creating helm-controller event broadcaster" machine # [ 26.712412] k3s[835]: I0913 15:16:38.630493 835 controller.go:667] quota admission added evaluator for: addons.k3s.cattle.io machine # [ 26.736107] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Cluster dns configmap has been set successfully" machine # [ 26.739341] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found" machine # [ 26.743062] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" object=kube-system/ccm reason=ApplyingManifest type=Normal machine # [ 26.944457] k3s[835]: I0913 15:16:38.862458 835 controllermanager.go:627] "Warning: controller is disabled" controller="cloud-node-lifecycle-controller" machine # [ 26.947052] k3s[835]: I0913 15:16:38.864408 835 controller_descriptor.go:99] "Controller is disabled by a feature gate" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller" requiredFeatureGates=["ClusterTrustBundle"] machine # [ 26.949636] k3s[835]: I0913 15:16:38.864439 835 controllermanager.go:579] "Warning: skipping controller" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller" machine # [ 27.097507] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" object=kube-system/ccm reason=AppliedManifest type=Normal machine # [ 27.114630] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/ci.yaml\"" object=kube-system/ci reason=ApplyingManifest type=Normal machine # [ 27.429079] k3s[835]: I0913 15:16:39.346348 835 serving.go:392] Generated self-signed cert in-memory machine # [ 27.431822] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ci.yaml\"" object=kube-system/ci reason=AppliedManifest type=Normal machine # [ 27.479635] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/coredns.yaml\"" object=kube-system/coredns reason=ApplyingManifest type=Normal machine # [ 27.650927] k3s[835]: I0913 15:16:39.568684 835 serving.go:392] Generated self-signed cert in-memory machine # [ 27.727145] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found" machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 27.742059] k3s[835]: I0913 15:16:39.659128 835 controllermanager.go:627] "Warning: controller is disabled" controller="node-route-controller" machine # [ 27.808459] k3s[835]: I0913 15:16:39.726525 835 controllermanager.go:160] Version: v1.35.8+k3s1 machine # [ 27.812510] k3s[835]: I0913 15:16:39.730604 835 secure_serving.go:211] Serving securely on 127.0.0.1:10258 machine # [ 27.814056] k3s[835]: I0913 15:16:39.731990 835 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController machine # [ 27.815569] k3s[835]: I0913 15:16:39.732184 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 27.816714] k3s[835]: I0913 15:16:39.732015 835 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 27.818736] k3s[835]: I0913 15:16:39.732228 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 27.820036] k3s[835]: I0913 15:16:39.732040 835 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 27.822349] k3s[835]: I0913 15:16:39.732259 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 27.823652] k3s[835]: I0913 15:16:39.732062 835 tlsconfig.go:243] "Starting DynamicServingCertificateController" machine # [ 27.824959] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Creating service-lb-controller event broadcaster" machine # [ 27.914897] k3s[835]: I0913 15:16:39.832959 835 shared_informer.go:377] "Caches are synced" machine # [ 27.917339] k3s[835]: I0913 15:16:39.833005 835 shared_informer.go:377] "Caches are synced" machine # [ 27.919042] k3s[835]: I0913 15:16:39.833068 835 shared_informer.go:377] "Caches are synced" machine # [ 27.934066] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding controller" machine # [ 27.938406] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting batch/v1, Kind=Job controller" machine # [ 27.939670] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=Secret controller" machine # [ 27.940803] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=ConfigMap controller" machine # [ 27.942166] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=ServiceAccount controller" machine # [ 27.945708] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller" machine # [ 27.947256] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller" machine # [ 28.053439] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=Node controller" machine # [ 28.060183] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=Pod controller" machine # [ 28.066603] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting apps/v1, Kind=DaemonSet controller" machine # [ 28.075057] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting discovery.k8s.io/v1, Kind=EndpointSlice controller" machine # [ 28.076594] k3s[835]: W0913 15:16:39.991719 835 controllermanager.go:306] "node-route-controller" is disabled machine # [ 28.077864] k3s[835]: I0913 15:16:39.992383 835 controllermanager.go:329] Started "cloud-node-controller" machine # [ 28.079121] k3s[835]: I0913 15:16:39.992680 835 controllermanager.go:329] Started "cloud-node-lifecycle-controller" machine # [ 28.080409] k3s[835]: I0913 15:16:39.992972 835 node_controller.go:176] Sending events to api server. machine # [ 28.081549] k3s[835]: I0913 15:16:39.993015 835 node_lifecycle_controller.go:112] Sending events to api server machine # [ 28.082839] k3s[835]: I0913 15:16:39.993374 835 controllermanager.go:329] Started "service-lb-controller" machine # [ 28.084068] k3s[835]: I0913 15:16:39.993819 835 node_controller.go:185] Waiting for informer caches to sync machine # [ 28.085502] k3s[835]: I0913 15:16:39.994041 835 controller.go:235] Starting service controller machine # [ 28.086683] k3s[835]: I0913 15:16:39.994061 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 28.192718] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/klipper-helm:v0.13.3-build20260727" machine # [ 28.204706] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/klipper-helm@sha256:5425a2b4613d2458dbdff99218e8d487ebb59c20e7a941f061c0777070f0aac1" machine # [ 28.206699] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/klipper-lb:v0.4.17" machine # [ 28.210607] k3s[835]: I0913 15:16:40.128688 835 controller.go:667] quota admission added evaluator for: deployments.apps machine # [ 28.215549] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/klipper-lb@sha256:910944bb0bd94f060a82a56ca1ea1c577d3e49b3473a093a47a985f32e92d94a" machine # [ 28.217735] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/local-path-provisioner:v0.0.37" machine # [ 28.219342] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/local-path-provisioner@sha256:e757967a5ec338f6a9b371c5a9688bedaa8c3578ea3dd4db329ea0084be0a86f" machine # [ 28.223140] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-coredns-coredns:1.14.6" machine # [ 28.224640] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-coredns-coredns@sha256:900f9c109f7a33545d3c811516e8376df9019147b750f5ce3e254468769176ea" machine # [ 28.226960] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-library-busybox:1.37.0" machine # [ 28.228651] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-library-busybox@sha256:101b4afd76732482eff9b95cae5f94bcf295e521fbec4e01b69c5421f3f3f3e5" machine # [ 28.231297] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-library-traefik:3.7.8" machine # [ 28.233347] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-library-traefik@sha256:4299bbed850421258fc5448c2e0e6ad350981d4d335a68de11b92448aedbefe5" machine # [ 28.236444] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-metrics-server:v0.9.0" machine # [ 28.240868] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-metrics-server@sha256:d9862115e7c7881280d3d75ca26bda8ffc0fc213315979575bf23ce9826205c0" machine # [ 28.243302] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-pause:3.10.2" machine # [ 28.249219] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-pause@sha256:f548e0e8e3dc1896ca956272154dde3314e8cc4fde0a57577ee9fa1c63f5baf4" machine # [ 28.277320] k3s[835]: I0913 15:16:40.195384 835 shared_informer.go:377] "Caches are synced" machine # [ 28.508502] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported 8 images from /var/lib/rancher/k3s/agent/images/k3s-airgap-images-amd64.tar.zst in 6.993733001s" machine # [ 28.510940] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Importing images from /var/lib/rancher/k3s/agent/images/niks3-server.tar" machine # [ 28.535686] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Running kubelet --cloud-provider=external --config-dir=/var/lib/rancher/k3s/agent/etc/kubelet.conf.d --containerd=/run/k3s/containerd/containerd.sock --hostname-override=machine --kubeconfig=/var/lib/rancher/k3s/agent/kubelet.kubeconfig --node-ip=10.0.2.15,fec0::5324:8bf6:15bd:aa25 --node-labels= --read-only-port=0" machine # [ 28.539601] k3s[835]: Flag --containerd has been deprecated, This is a cadvisor flag that was mistakenly registered with the Kubelet. Due to legacy concerns, it will follow the standard CLI deprecation timeline before being removed. machine # [ 28.553227] k3s[835]: I0913 15:16:40.471304 835 server.go:521] "Kubelet version" kubeletVersion="v1.35.8+k3s1" machine # [ 28.554641] k3s[835]: I0913 15:16:40.471328 835 server.go:523] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 28.556314] k3s[835]: I0913 15:16:40.471355 835 watchdog_linux.go:95] "Systemd watchdog is not enabled" machine # [ 28.557590] k3s[835]: I0913 15:16:40.471365 835 watchdog_linux.go:138] "Systemd watchdog is not enabled or the interval is invalid, so health checking will not be started." machine # [ 28.559694] k3s[835]: I0913 15:16:40.473345 835 dynamic_cafile_content.go:161] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt" machine # [ 28.562210] k3s[835]: I0913 15:16:40.480301 835 server.go:1414] "Using cgroup driver setting received from the CRI runtime" cgroupDriver="systemd" machine # [ 28.567410] k3s[835]: I0913 15:16:40.485500 835 server.go:771] "--cgroups-per-qos enabled, but --cgroup-root was not specified. Defaulting to /" machine # [ 28.569568] k3s[835]: I0913 15:16:40.485528 835 server.go:832] "NoSwap is set due to memorySwapBehavior not specified" memorySwapBehavior="" FailSwapOn=false machine # [ 28.569887] k3s[835]: I0913 15:16:40.485775 835 container_manager_linux.go:272] "Container manager verified user specified cgroup-root exists" cgroupRoot=[] machine # [ 28.570541] k3s[835]: I0913 15:16:40.485797 835 container_manager_linux.go:277] "Creating Container Manager object based on Node Config" nodeConfig={"NodeName":"machine","RuntimeCgroupsName":"","SystemCgroupsName":"","KubeletCgroupsName":"","KubeletOOMScoreAdj":-999,"ContainerRuntime":"","CgroupsPerQOS":true,"CgroupRoot":"/","CgroupDriver":"systemd","KubeletRootDir":"/var/lib/kubelet","ProtectKernelDefaults":false,"KubeReservedCgroupName":"","SystemReservedCgroupName":"","ReservedSystemCPUs":{},"EnforceNodeAllocatable":{"pods":{}},"KubeReserved":null,"SystemReserved":null,"HardEvictionThresholds":[{"Signal":"imagefs.available","Operator":"LessThan","Value":{"Quantity":null,"Percentage":0.05},"GracePeriod":0,"MinReclaim":null},{"Signal":"nodefs.available","Operator":"LessThan","Value":{"Quantity":null,"Percentage":0.05},"GracePeriod":0,"MinReclaim":null}],"QOSReserved":{},"CPUManagerPolicy":"none","CPUManagerPolicyOptions":null,"TopologyManagerScope":"container","CPUManagerReconcilePeriod":10000000000,"MemoryManagerPolicy":"None","MemoryManagerReservedMemory":null,"PodPidsLimit":-1,"EnforceCPULimits":true,"CPUCFSQuotaPeriod":100000000,"TopologyManagerPolicy":"none","TopologyManagerPolicyOptions":null,"CgroupVersion":2} machine # [ 28.571387] k3s[835]: I0913 15:16:40.486032 835 topology_manager.go:143] "Creating topology manager with none policy" machine # [ 28.572801] k3s[835]: I0913 15:16:40.486046 835 container_manager_linux.go:308] "Creating device plugin manager" machine # [ 28.573508] k3s[835]: I0913 15:16:40.486113 835 container_manager_linux.go:317] "Creating Dynamic Resource Allocation (DRA) manager" machine # [ 28.575126] k3s[835]: I0913 15:16:40.490521 835 state_mem.go:41] "Initialized" logger="CPUManager state memory" machine # [ 28.575821] k3s[835]: I0913 15:16:40.490812 835 kubelet.go:482] "Attempting to sync node with API server" machine # [ 28.576453] k3s[835]: I0913 15:16:40.490830 835 kubelet.go:383] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests" machine # [ 28.576894] k3s[835]: I0913 15:16:40.491006 835 kubelet.go:394] "Adding apiserver pod source" machine # [ 28.579767] k3s[835]: I0913 15:16:40.492225 835 apiserver.go:42] "Waiting for node sync before watching apiserver pods" machine # [ 28.594095] k3s[835]: I0913 15:16:40.512169 835 kuberuntime_manager.go:304] "Container runtime initialized" containerRuntime="containerd" version="2.2.7-k3s1" apiVersion="v1" machine # [ 28.597221] k3s[835]: I0913 15:16:40.515302 835 kubelet.go:945] "Not starting ClusterTrustBundle informer because we are in static kubelet mode or the ClusterTrustBundleProjection featuregate is disabled" machine # [ 28.597620] k3s[835]: I0913 15:16:40.515333 835 kubelet.go:972] "Not starting PodCertificateRequest manager because we are in static kubelet mode or the PodCertificateProjection feature gate is disabled" machine # [ 28.606148] k3s[835]: I0913 15:16:40.524205 835 server.go:1252] "Started kubelet" machine # [ 28.609056] k3s[835]: I0913 15:16:40.526555 835 server.go:182] "Starting to listen" address="0.0.0.0" port=10250 machine # [ 28.610993] k3s[835]: I0913 15:16:40.529081 835 server.go:317] "Adding debug handlers to kubelet server" machine # [ 28.613470] k3s[835]: I0913 15:16:40.531523 835 ratelimit.go:56] "Setting rate limiting for endpoint" service="podresources" qps=100 burstTokens=10 machine # [ 28.615498] k3s[835]: I0913 15:16:40.533565 835 server_v1.go:49] "podresources" method="list" useActivePods=true machine # [ 28.617318] k3s[835]: I0913 15:16:40.535406 835 server.go:254] "Starting to serve the podresources API" endpoint="unix:/var/lib/kubelet/pod-resources/kubelet.sock" machine # [ 28.620155] k3s[835]: I0913 15:16:40.538243 835 range_allocator.go:113] "No Secondary Service CIDR provided. Skipping filtering out secondary service addresses" logger="node-ipam-controller" machine # [ 28.624320] k3s[835]: E0913 15:16:40.542410 835 kubelet.go:1661] "Image garbage collection failed once. Stats initialization may not have completed yet" err="invalid capacity 0 on image filesystem" machine # [ 28.627094] k3s[835]: I0913 15:16:40.545166 835 fs_resource_analyzer.go:69] "Starting FS ResourceAnalyzer" machine # [ 28.635859] k3s[835]: I0913 15:16:40.553637 835 dynamic_serving_content.go:135] "Starting controller" name="kubelet-server-cert-files::/var/lib/rancher/k3s/agent/serving-kubelet.crt::/var/lib/rancher/k3s/agent/serving-kubelet.key" machine # [ 28.640217] k3s[835]: I0913 15:16:40.554887 835 alloc.go:329] "allocated clusterIPs" service="kube-system/kube-dns" clusterIPs={"IPv4":"10.43.0.10"} machine # [ 28.642495] k3s[835]: I0913 15:16:40.557239 835 volume_manager.go:311] "Starting Kubelet Volume Manager" machine # [ 28.643775] k3s[835]: E0913 15:16:40.557566 835 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found" machine # [ 28.646149] k3s[835]: I0913 15:16:40.563790 835 desired_state_of_world_populator.go:146] "Desired state populator starts to run" machine # [ 28.649162] k3s[835]: I0913 15:16:40.563858 835 reconciler.go:29] "Reconciler: start to sync state" machine # [ 28.653184] k3s[835]: I0913 15:16:40.570960 835 factory.go:221] Registration of the crio container factory failed: Get "http://%2Fvar%2Frun%2Fcrio%2Fcrio.sock/info": dial unix /var/run/crio/crio.sock: connect: no such file or directory machine # [ 28.656026] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/coredns.yaml\"" object=kube-system/coredns reason=AppliedManifest type=Normal machine # [ 28.666947] k3s[835]: I0913 15:16:40.584980 835 factory.go:223] Registration of the containerd container factory successfully machine # [ 28.669482] k3s[835]: I0913 15:16:40.585006 835 factory.go:223] Registration of the systemd container factory successfully machine # [ 28.688194] k3s[835]: E0913 15:16:40.606234 835 nodelease.go:50] "Failed to get node when trying to set owner ref to the node lease" err="nodes \"machine\" not found" node="machine" machine # [ 28.711059] k3s[835]: I0913 15:16:40.629065 835 cpu_manager.go:225] "Starting" policy="none" machine # [ 28.712811] k3s[835]: I0913 15:16:40.629125 835 cpu_manager.go:226] "Reconciling" reconcilePeriod="10s" machine # [ 28.714483] k3s[835]: I0913 15:16:40.630419 835 state_mem.go:41] "Initialized" logger="CPUManager state checkpoint.CPUManager state memory" machine # [ 28.717255] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found" machine # [ 28.719431] k3s[835]: I0913 15:16:40.635302 835 controllermanager.go:627] "Warning: controller is disabled" controller="service-lb-controller" machine # [ 28.721908] k3s[835]: I0913 15:16:40.639753 835 policy_none.go:50] "Start" machine # [ 28.723336] k3s[835]: I0913 15:16:40.639775 835 memory_manager.go:187] "Starting memorymanager" policy="None" machine # [ 28.725213] k3s[835]: I0913 15:16:40.639793 835 state_mem.go:36] "Initializing new in-memory state store" logger="Memory Manager state checkpoint" machine # [ 28.729423] k3s[835]: I0913 15:16:40.647500 835 policy_none.go:44] "Start" machine # [ 28.736904] systemd[1]: Created slice libcontainer container kubepods.slice. machine # [ 28.742720] k3s[835]: E0913 15:16:40.660808 835 kubelet_node_status.go:392] "Error getting the current node from lister" err="node \"machine\" not found" machine # [ 28.756964] systemd[1]: Created slice libcontainer container kubepods-burstable.slice. machine # [ 28.766680] systemd[1]: Created slice libcontainer container kubepods-besteffort.slice. machine # [ 28.775367] k3s[835]: E0913 15:16:40.693446 835 manager.go:525] "Failed to read data from checkpoint" err="checkpoint is not found" checkpoint="kubelet_internal_checkpoint" machine # [ 28.779612] k3s[835]: I0913 15:16:40.693570 835 eviction_manager.go:194] "Eviction manager: starting control loop" machine # [ 28.782405] k3s[835]: I0913 15:16:40.693593 835 container_log_manager.go:146] "Initializing container log rotate workers" workers=1 monitorPeriod="10s" machine # [ 28.784788] k3s[835]: I0913 15:16:40.694997 835 plugin_manager.go:121] "Starting Kubelet Plugin Manager" machine # [ 28.787142] k3s[835]: E0913 15:16:40.704911 835 eviction_manager.go:272] "eviction manager: failed to check if we have separate container filesystem. Ignoring." err="no imagefs label for configured runtime" machine # [ 28.789510] k3s[835]: E0913 15:16:40.704943 835 eviction_manager.go:297] "Eviction manager: failed to get summary stats" err="failed to get node info: node \"machine\" not found" machine # [ 28.880251] k3s[835]: I0913 15:16:40.798100 835 kubelet_node_status.go:74] "Attempting to register node" node="machine" machine # [ 28.906064] k3s[835]: I0913 15:16:40.823936 835 kubelet_node_status.go:77] "Successfully registered node" node="machine" machine # [ 28.920663] k3s[835]: I0913 15:16:40.836888 835 node_controller.go:429] Initializing node machine with cloud provider machine # [ 28.922394] k3s[835]: I0913 15:16:40.839116 835 node_controller.go:233] error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing machine # [ 28.924604] k3s[835]: E0913 15:16:40.839176 835 node_controller.go:244] "Unhandled Error" err="error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing" logger="UnhandledError" machine # [ 28.928153] k3s[835]: I0913 15:16:40.841485 835 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv4" machine # [ 28.930211] k3s[835]: I0913 15:16:40.843944 835 node_controller.go:429] Initializing node machine with cloud provider machine # [ 28.931907] k3s[835]: I0913 15:16:40.843985 835 node_controller.go:233] error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing machine # [ 28.935076] k3s[835]: E0913 15:16:40.844003 835 node_controller.go:244] "Unhandled Error" err="error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing" logger="UnhandledError" machine # [ 28.939557] k3s[835]: I0913 15:16:40.857550 835 node_controller.go:429] Initializing node machine with cloud provider machine # [ 28.941033] k3s[835]: I0913 15:16:40.857622 835 node_controller.go:233] error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing machine # [ 28.944032] k3s[835]: E0913 15:16:40.857641 835 node_controller.go:244] "Unhandled Error" err="error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing" logger="UnhandledError" machine # [ 28.951491] k3s[835]: I0913 15:16:40.868456 835 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv6" machine # [ 28.955166] k3s[835]: I0913 15:16:40.868480 835 status_manager.go:249] "Starting to sync pod status with apiserver" machine # [ 28.956585] k3s[835]: I0913 15:16:40.868510 835 kubelet.go:2506] "Starting kubelet main sync loop" machine # [ 28.957700] k3s[835]: E0913 15:16:40.869595 835 kubelet.go:2530] "Skipping pod synchronization" err="PLEG is not healthy: pleg has yet to be successful" machine # [ 28.960494] k3s[835]: I0913 15:16:40.878585 835 node_controller.go:429] Initializing node machine with cloud provider machine # [ 28.964305] k3s[835]: I0913 15:16:40.882388 835 node_controller.go:233] error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing machine # [ 28.968950] k3s[835]: E0913 15:16:40.887043 835 node_controller.go:244] "Unhandled Error" err="error syncing 'machine': failed to get instance metadata for node machine: address annotations not yet set, requeuing" logger="UnhandledError" machine # [ 28.977507] k3s[835]: I0913 15:16:40.895603 835 node_controller.go:429] Initializing node machine with cloud provider machine # [ 28.984419] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Annotations and labels have been set successfully on node: machine" machine # [ 28.988222] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Synced coredns NodeHosts entries for machine" machine # [ 28.990230] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Starting flannel with backend vxlan" machine # [ 29.050827] k3s[835]: I0913 15:16:40.968847 835 node_controller.go:474] Successfully initialized node machine with cloud provider machine # [ 29.054261] k3s[835]: I0913 15:16:40.971994 835 event.go:389] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="v1" type="Normal" reason="Synced" message="Node synced successfully" machine # [ 29.068993] k3s[835]: I0913 15:16:40.987079 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.076068] k3s[835]: I0913 15:16:40.994124 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.077506] k3s[835]: I0913 15:16:40.995560 835 namespace_controller.go:202] "Starting namespace controller" machine # [ 29.080065] k3s[835]: I0913 15:16:40.996925 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.081316] k3s[835]: I0913 15:16:40.996963 835 ttl_controller.go:127] "Starting TTL controller" machine # [ 29.082413] k3s[835]: I0913 15:16:40.997006 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.083537] k3s[835]: I0913 15:16:40.997043 835 expand_controller.go:328] "Starting expand controller" machine # [ 29.084722] k3s[835]: I0913 15:16:40.997086 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.086054] k3s[835]: I0913 15:16:40.997122 835 controller.go:174] "Starting ephemeral volume controller" machine # [ 29.087234] k3s[835]: I0913 15:16:40.997161 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.088397] k3s[835]: I0913 15:16:40.997247 835 replica_set.go:241] "Starting controller" name="replicationcontroller" machine # [ 29.089722] k3s[835]: I0913 15:16:40.997278 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.090912] k3s[835]: I0913 15:16:40.997373 835 replica_set.go:241] "Starting controller" name="replicaset" machine # [ 29.092098] k3s[835]: I0913 15:16:40.997393 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.093224] k3s[835]: I0913 15:16:40.997427 835 disruption.go:458] "Sending events to api server." machine # [ 29.094341] k3s[835]: I0913 15:16:40.997514 835 disruption.go:465] "Starting disruption controller" machine # [ 29.095465] k3s[835]: I0913 15:16:40.997524 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.096613] k3s[835]: I0913 15:16:40.997634 835 vac_protection_controller.go:206] "Starting VAC protection controller" machine # [ 29.097932] k3s[835]: I0913 15:16:40.997652 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.099143] k3s[835]: I0913 15:16:40.997680 835 ttlafterfinished_controller.go:112] "Starting TTL after finished controller" machine # [ 29.100628] k3s[835]: I0913 15:16:40.997699 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.101797] k3s[835]: I0913 15:16:40.997977 835 job_controller.go:254] "Starting job controller" machine # [ 29.102909] k3s[835]: I0913 15:16:40.998023 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.107214] k3s[835]: I0913 15:16:40.998088 835 horizontal.go:204] "Starting HPA controller" machine # [ 29.108353] k3s[835]: I0913 15:16:40.998106 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.109585] k3s[835]: I0913 15:16:41.022390 835 certificate_controller.go:120] "Starting certificate controller" name="csrapproving" machine # [ 29.110995] k3s[835]: I0913 15:16:41.022421 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.112194] k3s[835]: I0913 15:16:41.022501 835 node_lifecycle_controller.go:453] "Sending events to api server" machine # [ 29.113547] k3s[835]: I0913 15:16:41.022539 835 node_lifecycle_controller.go:460] "Starting node controller" machine # [ 29.114760] k3s[835]: I0913 15:16:41.022548 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.115889] k3s[835]: I0913 15:16:41.022639 835 endpointslice_controller.go:283] "Starting endpoint slice controller" machine # [ 29.117224] k3s[835]: I0913 15:16:41.022693 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.118348] k3s[835]: I0913 15:16:41.022726 835 serviceaccounts_controller.go:117] "Starting service account controller" machine # [ 29.119672] k3s[835]: I0913 15:16:41.022744 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.120785] k3s[835]: I0913 15:16:41.023460 835 attach_detach_controller.go:335] "Starting attach detach controller" machine # [ 29.122091] k3s[835]: I0913 15:16:41.023484 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.123252] k3s[835]: I0913 15:16:41.023517 835 pvc_protection_controller.go:166] "Starting PVC protection controller" machine # [ 29.124836] k3s[835]: I0913 15:16:41.023534 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.126031] k3s[835]: I0913 15:16:41.023714 835 publisher.go:107] "Starting root CA cert publisher controller" machine # [ 29.127899] k3s[835]: I0913 15:16:41.023747 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.129507] k3s[835]: I0913 15:16:41.023866 835 controller.go:423] "Starting resource claim controller" machine # [ 29.131217] k3s[835]: I0913 15:16:41.023883 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.132836] k3s[835]: I0913 15:16:41.023917 835 taint_eviction.go:283] "Starting" controller="taint-eviction-controller" machine # [ 29.134671] k3s[835]: I0913 15:16:41.024105 835 taint_eviction.go:288] "Sending events to API server" machine # [ 29.135846] k3s[835]: I0913 15:16:41.024116 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.137590] k3s[835]: I0913 15:16:41.024752 835 deployment_controller.go:172] "Starting controller" controller="deployment" machine # [ 29.139697] k3s[835]: I0913 15:16:41.024773 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.141486] k3s[835]: I0913 15:16:41.043053 835 stateful_set.go:180] "Starting stateful set controller" machine # [ 29.145347] k3s[835]: I0913 15:16:41.043084 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.147045] k3s[835]: I0913 15:16:41.043294 835 legacy_serviceaccount_token_cleaner.go:103] "Starting legacy service account token cleaner controller" machine # [ 29.149409] k3s[835]: I0913 15:16:41.043308 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.151106] k3s[835]: I0913 15:16:41.043602 835 servicecidrs_controller.go:136] "Starting" controller="service-cidr-controller" machine # [ 29.152788] k3s[835]: I0913 15:16:41.043617 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.153894] k3s[835]: I0913 15:16:41.043810 835 endpoints_controller.go:193] "Starting endpoint controller" machine # [ 29.155127] k3s[835]: I0913 15:16:41.043823 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.156282] k3s[835]: I0913 15:16:41.044009 835 endpointslicemirroring_controller.go:226] "Starting EndpointSliceMirroring controller" machine # [ 29.157704] k3s[835]: I0913 15:16:41.044023 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.158830] k3s[835]: I0913 15:16:41.044378 835 daemon_controller.go:309] "Starting daemon sets controller" machine # [ 29.160053] k3s[835]: I0913 15:16:41.044395 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.161177] k3s[835]: I0913 15:16:41.044582 835 cleaner.go:83] "Starting CSR cleaner controller" machine # [ 29.162231] k3s[835]: I0913 15:16:41.045424 835 pv_controller_base.go:307] "Starting persistent volume controller" machine # [ 29.163430] k3s[835]: I0913 15:16:41.045441 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.164533] k3s[835]: I0913 15:16:41.045857 835 pv_protection_controller.go:81] "Starting PV protection controller" machine # [ 29.165834] k3s[835]: I0913 15:16:41.045872 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.166975] k3s[835]: I0913 15:16:41.046520 835 cronjob_controllerv2.go:143] "Starting cronjob controller v2" machine # [ 29.168305] k3s[835]: I0913 15:16:41.046537 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.169416] k3s[835]: I0913 15:16:41.047122 835 node_ipam_controller.go:142] "Starting ipam controller" machine # [ 29.170623] k3s[835]: I0913 15:16:41.047163 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.171820] k3s[835]: I0913 15:16:41.047485 835 gc_controller.go:98] "Starting GC controller" machine # [ 29.173526] k3s[835]: I0913 15:16:41.047499 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.174706] k3s[835]: I0913 15:16:41.047603 835 tokencleaner.go:117] "Starting token cleaner controller" machine # [ 29.175955] k3s[835]: I0913 15:16:41.047665 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.177105] k3s[835]: I0913 15:16:41.047753 835 clusterroleaggregation_controller.go:194] "Starting ClusterRoleAggregator controller" machine # [ 29.178614] k3s[835]: I0913 15:16:41.047764 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.179804] k3s[835]: I0913 15:16:41.050301 835 garbagecollector.go:141] "Starting controller" controller="garbagecollector" machine # [ 29.181144] k3s[835]: I0913 15:16:41.050341 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.182325] k3s[835]: I0913 15:16:41.050812 835 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-serving" machine # [ 29.183819] k3s[835]: I0913 15:16:41.050832 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.185030] k3s[835]: I0913 15:16:41.051081 835 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-client" machine # [ 29.186674] k3s[835]: I0913 15:16:41.051117 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.187877] k3s[835]: I0913 15:16:41.051365 835 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kube-apiserver-client" machine # [ 29.189501] k3s[835]: I0913 15:16:41.051384 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.190607] k3s[835]: I0913 15:16:41.051652 835 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-legacy-unknown" machine # [ 29.192870] k3s[835]: I0913 15:16:41.051671 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.194069] k3s[835]: I0913 15:16:41.054895 835 resource_quota_controller.go:297] "Starting resource quota controller" machine # [ 29.195440] k3s[835]: I0913 15:16:41.054926 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.196595] k3s[835]: I0913 15:16:41.059052 835 graph_builder.go:386] "Running" component="GraphBuilder" machine # [ 29.197851] k3s[835]: I0913 15:16:41.059339 835 dynamic_serving_content.go:135] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/server-ca.key" machine # [ 29.200212] k3s[835]: I0913 15:16:41.061400 835 dynamic_serving_content.go:135] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/client-ca.key" machine # [ 29.202506] k3s[835]: I0913 15:16:41.061839 835 dynamic_serving_content.go:135] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/client-ca.key" machine # [ 29.204768] k3s[835]: I0913 15:16:41.062172 835 dynamic_serving_content.go:135] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/server-ca.key" machine # [ 29.207021] k3s[835]: I0913 15:16:41.062552 835 resource_quota_monitor.go:309] "QuotaMonitor running" machine # [ 29.218061] k3s[835]: I0913 15:16:41.135555 835 server.go:173] "Starting Kubernetes Scheduler" version="v1.35.8+k3s1" machine # [ 29.219932] k3s[835]: I0913 15:16:41.135583 835 server.go:175] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 29.238252] k3s[835]: I0913 15:16:41.156331 835 kubelet_node_status.go:427] "Fast updating node status as it just became ready" machine # [ 29.244051] k3s[835]: I0913 15:16:41.161354 835 shared_informer.go:370] "Waiting for caches to sync" machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 29.275287] k3s[835]: I0913 15:16:41.193367 835 secure_serving.go:211] Serving securely on 127.0.0.1:10259 machine # [ 29.279281] k3s[835]: I0913 15:16:41.197374 835 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController machine # [ 29.280743] k3s[835]: I0913 15:16:41.198839 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.282037] k3s[835]: I0913 15:16:41.200112 835 dynamic_serving_content.go:135] "Starting controller" name="serving-cert::/var/lib/rancher/k3s/server/tls/kube-scheduler/kube-scheduler.crt::/var/lib/rancher/k3s/server/tls/kube-scheduler/kube-scheduler.key" machine # [ 29.284877] k3s[835]: I0913 15:16:41.202976 835 tlsconfig.go:243] "Starting DynamicServingCertificateController" machine # [ 29.289761] k3s[835]: I0913 15:16:41.207839 835 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 29.291797] k3s[835]: I0913 15:16:41.209901 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.293067] k3s[835]: I0913 15:16:41.211166 835 configmap_cafile_content.go:205] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 29.295180] k3s[835]: I0913 15:16:41.213286 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.313613] k3s[835]: I0913 15:16:41.231631 835 actual_state_of_world.go:541] "Failed to update statusUpdateNeeded field in actual state of world" logger="persistentvolume-attach-detach-controller" err="Failed to set statusUpdateNeeded to needed true, because nodeName=\"machine\" does not exist" machine # [ 29.322519] k3s[835]: I0913 15:16:41.240596 835 shared_informer.go:377] "Caches are synced" machine # [ 29.345479] k3s[835]: I0913 15:16:41.263568 835 shared_informer.go:377] "Caches are synced" machine # [ 29.349225] k3s[835]: I0913 15:16:41.267204 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.350704] k3s[835]: I0913 15:16:41.264461 835 shared_informer.go:377] "Caches are synced" machine # [ 29.358270] k3s[835]: I0913 15:16:41.276353 835 range_allocator.go:177] "Sending events to api server" machine # [ 29.359541] k3s[835]: I0913 15:16:41.276426 835 range_allocator.go:181] "Starting range CIDR allocator" machine # [ 29.360751] k3s[835]: I0913 15:16:41.276437 835 shared_informer.go:370] "Waiting for caches to sync" machine # [ 29.361928] k3s[835]: I0913 15:16:41.276450 835 shared_informer.go:377] "Caches are synced" machine # [ 29.382060] k3s[835]: I0913 15:16:41.299742 835 shared_informer.go:377] "Caches are synced" machine # [ 29.383243] k3s[835]: I0913 15:16:41.299803 835 shared_informer.go:377] "Caches are synced" machine # [ 29.404741] k3s[835]: I0913 15:16:41.322812 835 range_allocator.go:433] "Set node PodCIDR" node="machine" podCIDRs=["10.42.0.0/24"] machine # [ 29.414063] k3s[835]: I0913 15:16:41.330699 835 shared_informer.go:377] "Caches are synced" machine # [ 29.415235] k3s[835]: I0913 15:16:41.330784 835 shared_informer.go:377] "Caches are synced" machine # [ 29.416398] k3s[835]: I0913 15:16:41.330842 835 shared_informer.go:377] "Caches are synced" machine # [ 29.425648] k3s[835]: I0913 15:16:41.343735 835 shared_informer.go:377] "Caches are synced" machine # [ 29.426877] k3s[835]: I0913 15:16:41.344504 835 shared_informer.go:377] "Caches are synced" machine # [ 29.427991] k3s[835]: I0913 15:16:41.345696 835 shared_informer.go:377] "Caches are synced" machine # [ 29.429089] k3s[835]: I0913 15:16:41.346034 835 shared_informer.go:377] "Caches are synced" machine # [ 29.430176] k3s[835]: I0913 15:16:41.347116 835 shared_informer.go:377] "Caches are synced" machine # [ 29.431249] k3s[835]: I0913 15:16:41.347640 835 shared_informer.go:377] "Caches are synced" machine # [ 29.432249] k3s[835]: I0913 15:16:41.348209 835 shared_informer.go:377] "Caches are synced" machine # [ 29.433354] k3s[835]: I0913 15:16:41.348390 835 shared_informer.go:377] "Caches are synced" machine # [ 29.434481] k3s[835]: I0913 15:16:41.351022 835 shared_informer.go:377] "Caches are synced" machine # [ 29.435575] k3s[835]: I0913 15:16:41.351227 835 shared_informer.go:377] "Caches are synced" machine # [ 29.436661] k3s[835]: I0913 15:16:41.351524 835 shared_informer.go:377] "Caches are synced" machine # [ 29.437735] k3s[835]: I0913 15:16:41.351838 835 shared_informer.go:377] "Caches are synced" machine # [ 29.438857] k3s[835]: I0913 15:16:41.355208 835 shared_informer.go:377] "Caches are synced" machine # [ 29.445651] k3s[835]: I0913 15:16:41.363734 835 shared_informer.go:377] "Caches are synced" machine # [ 29.471066] k3s[835]: I0913 15:16:41.388455 835 shared_informer.go:377] "Caches are synced" machine # [ 29.477494] k3s[835]: I0913 15:16:41.395567 835 shared_informer.go:377] "Caches are synced" machine # [ 29.479052] k3s[835]: I0913 15:16:41.397128 835 shared_informer.go:377] "Caches are synced" machine # [ 29.480182] k3s[835]: I0913 15:16:41.397203 835 shared_informer.go:377] "Caches are synced" machine # [ 29.481253] k3s[835]: I0913 15:16:41.397320 835 shared_informer.go:377] "Caches are synced" machine # [ 29.482334] k3s[835]: I0913 15:16:41.397474 835 shared_informer.go:377] "Caches are synced" machine # [ 29.483405] k3s[835]: I0913 15:16:41.397661 835 shared_informer.go:377] "Caches are synced" machine # [ 29.484508] k3s[835]: I0913 15:16:41.397709 835 shared_informer.go:377] "Caches are synced" machine # [ 29.485599] k3s[835]: I0913 15:16:41.397740 835 shared_informer.go:377] "Caches are synced" machine # [ 29.486697] k3s[835]: I0913 15:16:41.398064 835 shared_informer.go:377] "Caches are synced" machine # [ 29.487741] k3s[835]: I0913 15:16:41.398172 835 shared_informer.go:377] "Caches are synced" machine # [ 29.505097] k3s[835]: I0913 15:16:41.422479 835 shared_informer.go:377] "Caches are synced" machine # [ 29.506361] k3s[835]: I0913 15:16:41.422660 835 shared_informer.go:377] "Caches are synced" machine # [ 29.507635] k3s[835]: I0913 15:16:41.422741 835 node_lifecycle_controller.go:1234] "Initializing eviction metric for zone" zone="" machine # [ 29.509209] k3s[835]: I0913 15:16:41.422809 835 shared_informer.go:377] "Caches are synced" machine # [ 29.528073] k3s[835]: I0913 15:16:41.445736 835 shared_informer.go:377] "Caches are synced" machine # [ 29.529261] k3s[835]: I0913 15:16:41.445885 835 node_lifecycle_controller.go:886] "Missing timestamp for Node. Assuming now as a timestamp" node="machine" machine # [ 29.530915] k3s[835]: I0913 15:16:41.445948 835 node_lifecycle_controller.go:1080] "Controller detected that zone is now in new state" zone="" newState="Normal" machine # [ 29.532574] k3s[835]: I0913 15:16:41.445993 835 shared_informer.go:377] "Caches are synced" machine # [ 29.533631] k3s[835]: I0913 15:16:41.446038 835 topologycache.go:237] "Can't get CPU or zone information for node" node="machine" machine # [ 29.535156] k3s[835]: I0913 15:16:41.446450 835 shared_informer.go:377] "Caches are synced" machine # [ 29.536220] k3s[835]: I0913 15:16:41.446531 835 shared_informer.go:377] "Caches are synced" machine # [ 29.537241] k3s[835]: I0913 15:16:41.446815 835 shared_informer.go:377] "Caches are synced" machine # [ 29.538344] k3s[835]: I0913 15:16:41.446931 835 shared_informer.go:377] "Caches are synced" machine # [ 29.539435] k3s[835]: I0913 15:16:41.447453 835 shared_informer.go:377] "Caches are synced" machine # [ 29.540526] k3s[835]: I0913 15:16:41.447628 835 shared_informer.go:377] "Caches are synced" machine # [ 29.541566] k3s[835]: I0913 15:16:41.447803 835 shared_informer.go:377] "Caches are synced" machine # [ 29.579865] k3s[835]: I0913 15:16:41.496702 835 apiserver.go:52] "Watching apiserver" machine # [ 29.599696] k3s[835]: I0913 15:16:41.517764 835 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/16 machine # [ 29.601283] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Event occurred" apiVersion= fieldPath= kind=Node logger=k3s message="Deferred node password secret validation complete" object=machine reason=NodePasswordValidationComplete type=Normal machine # [ 29.603896] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Deleting manifest at \"/var/lib/rancher/k3s/server/manifests/local-storage.yaml\"" object=kube-system/local-storage reason=DeletingManifest type=Normal machine # [ 29.615872] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/niks3.yaml\"" object=kube-system/niks3 reason=ApplyingManifest type=Normal machine # [ 29.625560] k3s[835]: I0913 15:16:41.543457 835 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/16 machine # [ 29.645811] k3s[835]: I0913 15:16:41.563877 835 desired_state_of_world_populator.go:154] "Finished populating initial desired state of world" machine # [ 29.667870] k3s[835]: I0913 15:16:41.585404 835 controller.go:667] quota admission added evaluator for: helmcharts.helm.cattle.io machine # [ 29.672076] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/niks3.yaml\"" object=kube-system/niks3 reason=AppliedManifest type=Normal machine # [ 29.686358] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/rolebindings.yaml\"" object=kube-system/rolebindings reason=ApplyingManifest type=Normal machine # [ 29.715741] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Adding node OwnerReference to node-password secret machine.node-password.k3s" machine # [ 29.718162] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Labels and annotations have been set successfully on node: machine" machine # [ 29.729214] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Event occurred" apiVersion=helm.cattle.io/v1 fieldPath= kind=HelmChart logger=k3s/helm-controller message="Applying HelmChart from https://%{KUBERNETES_API}%/static/charts/niks3.tgz using Job kube-system/helm-install-niks3 " object=kube-system/niks3 reason=ApplyJob type=Normal machine # [ 29.761863] k3s[835]: I0913 15:16:41.679940 835 controller.go:667] quota admission added evaluator for: jobs.batch machine # [ 29.886918] k3s[835]: I0913 15:16:41.804616 835 server.go:218] "Successfully retrieved NodeIPs" NodeIPs=["10.0.2.15","fec0::5324:8bf6:15bd:aa25"] machine # [ 29.887476] k3s[835]: E0913 15:16:41.804898 835 server.go:255] "Kube-proxy configuration may be incomplete or incorrect" err="nodePortAddresses is unset; NodePort connections will be accepted on all local IPs. Consider using `--nodeport-addresses primary`" machine # [ 29.917065] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/rolebindings.yaml\"" object=kube-system/rolebindings reason=AppliedManifest type=Normal machine # [ 29.942127] k3s[835]: I0913 15:16:41.860171 835 server.go:264] "kube-proxy running in dual-stack mode" primary ipFamily="IPv4" machine # [ 29.944481] k3s[835]: I0913 15:16:41.860212 835 server_linux.go:136] "Using iptables Proxier" machine # [ 29.950057] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/runtimes.yaml\"" object=kube-system/runtimes reason=ApplyingManifest type=Normal machine # [ 29.965057] k3s[835]: I0913 15:16:41.882790 835 controller.go:667] quota admission added evaluator for: replicasets.apps machine # [ 29.990324] k3s[835]: I0913 15:16:41.908397 835 proxier.go:242] "Setting route_localnet=1 to allow node-ports on localhost; to change this either disable iptables.localhostNodePorts (--iptables-localhost-nodeports) or set nodePortAddresses (--nodeport-addresses) to filter loopback addresses" ipFamily="IPv4" machine # [ 30.024881] k3s[835]: I0913 15:16:41.942935 835 server.go:529] "Version info" version="v1.35.8+k3s1" machine # [ 30.026220] k3s[835]: I0913 15:16:41.942972 835 server.go:531] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 30.027890] k3s[835]: I0913 15:16:41.944424 835 config.go:200] "Starting service config controller" machine # [ 30.029948] k3s[835]: I0913 15:16:41.944443 835 shared_informer.go:349] "Waiting for caches to sync" controller="service config" machine # [ 30.031737] k3s[835]: I0913 15:16:41.944472 835 config.go:106] "Starting endpoint slice config controller" machine # [ 30.033795] k3s[835]: I0913 15:16:41.944486 835 shared_informer.go:349] "Waiting for caches to sync" controller="endpoint slice config" machine # [ 30.036079] k3s[835]: I0913 15:16:41.944513 835 config.go:403] "Starting serviceCIDR config controller" machine # [ 30.038084] k3s[835]: I0913 15:16:41.944525 835 shared_informer.go:349] "Waiting for caches to sync" controller="serviceCIDR config" machine # [ 30.039725] k3s[835]: I0913 15:16:41.944962 835 config.go:309] "Starting node config controller" machine # [ 30.041568] k3s[835]: I0913 15:16:41.944975 835 shared_informer.go:349] "Waiting for caches to sync" controller="node config" machine # [ 30.043227] k3s[835]: I0913 15:16:41.944986 835 shared_informer.go:356] "Caches are synced" controller="node config" machine # [ 30.092154] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/runtimes.yaml\"" object=kube-system/runtimes reason=AppliedManifest type=Normal machine # [ 30.155561] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Flannel found PodCIDR assigned for node machine" machine # [ 30.157055] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="The interface eth0 with ipv4 address 10.0.2.15 will be used by flannel" machine # [ 30.159136] k3s[835]: I0913 15:16:42.074656 835 kube.go:139] Waiting 10m0s for node controller to sync machine # [ 30.160631] k3s[835]: I0913 15:16:42.074771 835 kube.go:537] Starting kube subnet manager machine # [ 30.177888] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Event occurred" apiVersion=k3s.cattle.io/v1 fieldPath= kind=Addon logger=k3s/deploy message="Deleting manifest at \"/var/lib/rancher/k3s/server/manifests/traefik.yaml\"" object=kube-system/traefik reason=DeletingManifest type=Normal machine # [ 30.188720] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Event occurred" apiVersion=helm.cattle.io/v1 fieldPath= kind=HelmChart logger=k3s/helm-controller message="Resumed synced Job kube-system/helm-install-niks3" object=kube-system/niks3 reason=ResumeJob type=Normal machine # [ 30.227437] k3s[835]: I0913 15:16:42.145485 835 shared_informer.go:356] "Caches are synced" controller="serviceCIDR config" machine # [ 30.227821] k3s[835]: I0913 15:16:42.145559 835 shared_informer.go:356] "Caches are synced" controller="service config" machine # [ 30.228377] k3s[835]: I0913 15:16:42.145586 835 shared_informer.go:356] "Caches are synced" controller="endpoint slice config" machine # [ 30.361490] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Tunnel authorizer set Kubelet Port 0.0.0.0:10250" machine # [ 30.431630] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Imported docker.io/library/niks3-server:1.4.0-x86_64-linux" machine # [ 30.434925] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Tagged docker.io/library/niks3-server@sha256:c72a0c846cd0f611b79ee797431374f3eb618c301ca7a268547b626fe83377df" machine # [ 30.473410] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Imported 1 images from /var/lib/rancher/k3s/agent/images/niks3-server.tar in 1.96405409s" machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 30.649298] k3s[835]: I0913 15:16:42.567302 835 shared_informer.go:377] "Caches are synced" machine # [ 30.728287] k3s[835]: E0913 15:16:42.644021 835 status_manager.go:1045] "Failed to get status for pod" err="pods \"helm-install-niks3-6nlqx\" is forbidden: User \"system:node:machine\" cannot get resource \"pods\" in API group \"\" in the namespace \"kube-system\": no relationship found between node 'machine' and this object" podUID="338ed778-f4f8-41b0-8078-3ebdce579742" pod="kube-system/helm-install-niks3-6nlqx" machine # [ 30.752397] systemd[1]: Created slice libcontainer container kubepods-burstable-pod338ed778_f4f8_41b0_8078_3ebdce579742.slice. machine # [ 30.762522] k3s[835]: I0913 15:16:42.680600 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-helm\") pod \"helm-install-niks3-6nlqx\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " pod="kube-system/helm-install-niks3-6nlqx" machine # [ 30.766454] k3s[835]: I0913 15:16:42.680641 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-cache\") pod \"helm-install-niks3-6nlqx\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " pod="kube-system/helm-install-niks3-6nlqx" machine # [ 30.771541] k3s[835]: I0913 15:16:42.680665 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"values\" (UniqueName: \"kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-values\") pod \"helm-install-niks3-6nlqx\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " pod="kube-system/helm-install-niks3-6nlqx" machine # [ 30.775236] k3s[835]: I0913 15:16:42.680691 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"content\" (UniqueName: \"kubernetes.io/configmap/338ed778-f4f8-41b0-8078-3ebdce579742-content\") pod \"helm-install-niks3-6nlqx\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " pod="kube-system/helm-install-niks3-6nlqx" machine # [ 30.778910] k3s[835]: I0913 15:16:42.680717 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-config\") pod \"helm-install-niks3-6nlqx\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " pod="kube-system/helm-install-niks3-6nlqx" machine # [ 30.784544] k3s[835]: I0913 15:16:42.680743 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-tmp\") pod \"helm-install-niks3-6nlqx\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " pod="kube-system/helm-install-niks3-6nlqx" machine # [ 30.789064] k3s[835]: I0913 15:16:42.680772 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-kqlm2\" (UniqueName: \"kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-kube-api-access-kqlm2\") pod \"helm-install-niks3-6nlqx\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " pod="kube-system/helm-install-niks3-6nlqx" machine # [ 30.793522] k3s[835]: I0913 15:16:42.680800 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"config-volume\" (UniqueName: \"kubernetes.io/configmap/c7fa4117-0e7f-496c-8354-68d774a9432f-config-volume\") pod \"coredns-c5fdd76cf-768vm\" (UID: \"c7fa4117-0e7f-496c-8354-68d774a9432f\") " pod="kube-system/coredns-c5fdd76cf-768vm" machine # [ 30.803250] k3s[835]: I0913 15:16:42.680828 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"custom-config-volume\" (UniqueName: \"kubernetes.io/configmap/c7fa4117-0e7f-496c-8354-68d774a9432f-custom-config-volume\") pod \"coredns-c5fdd76cf-768vm\" (UID: \"c7fa4117-0e7f-496c-8354-68d774a9432f\") " pod="kube-system/coredns-c5fdd76cf-768vm" machine # [ 30.807190] k3s[835]: I0913 15:16:42.680853 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-4jqp9\" (UniqueName: \"kubernetes.io/projected/c7fa4117-0e7f-496c-8354-68d774a9432f-kube-api-access-4jqp9\") pod \"coredns-c5fdd76cf-768vm\" (UID: \"c7fa4117-0e7f-496c-8354-68d774a9432f\") " pod="kube-system/coredns-c5fdd76cf-768vm" machine # [ 30.816516] k3s[835]: I0913 15:16:42.684518 835 shared_informer.go:377] "Caches are synced" machine # [ 30.817880] k3s[835]: I0913 15:16:42.686248 835 garbagecollector.go:166] "Garbage collector: all resource monitors have synced" machine # [ 30.819357] k3s[835]: I0913 15:16:42.686261 835 garbagecollector.go:169] "Proceeding to collect garbage" machine # [ 30.820590] systemd[1]: Created slice libcontainer container kubepods-burstable-podc7fa4117_0e7f_496c_8354_68d774a9432f.slice. machine # [ 31.157629] k3s[835]: I0913 15:16:43.075339 835 kube.go:163] Node controller sync successful machine # [ 31.159024] k3s[835]: I0913 15:16:43.075420 835 vxlan.go:128] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false machine # [ 31.164483] k3s[835]: I0913 15:16:43.082567 835 kube.go:704] List of node(machine) annotations: map[string]string{"alpha.kubernetes.io/provided-node-ip":"10.0.2.15,fec0::5324:8bf6:15bd:aa25", "k3s.io/hostname":"machine", "k3s.io/internal-ip":"10.0.2.15,fec0::5324:8bf6:15bd:aa25", "k3s.io/node-args":"[\"server\",\"--disable\",\"traefik\",\"--disable\",\"metrics-server\",\"--disable\",\"local-storage\"]", "k3s.io/node-config-hash":"B5VKUCD5GTR3QGINHIAWYQ4H226RXO3OMZ3SDCJYGSY4JRMNFBRQ====", "k3s.io/node-env":"{}", "node.alpha.kubernetes.io/ttl":"0", "volumes.kubernetes.io/controller-managed-attach-detach":"true"} machine # [ 31.230498] k3s[835]: I0913 15:16:43.148080 835 iptables.go:50] Starting flannel in iptables mode... machine # [ 31.231896] k3s[835]: time="2026-09-13T15:16:43Z" level=warning msg="no subnet found for key: FLANNEL_NETWORK in file: /run/flannel/subnet.env" machine # [ 31.234514] k3s[835]: time="2026-09-13T15:16:43Z" level=warning msg="no subnet found for key: FLANNEL_SUBNET in file: /run/flannel/subnet.env" machine # [ 31.236918] k3s[835]: time="2026-09-13T15:16:43Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_NETWORK in file: /run/flannel/subnet.env" machine # [ 31.239374] k3s[835]: time="2026-09-13T15:16:43Z" level=warning msg="no subnet found for key: FLANNEL_IPV6_SUBNET in file: /run/flannel/subnet.env" machine # [ 31.243956] k3s[835]: I0913 15:16:43.149553 835 iptables.go:101] Current network or subnet (10.42.0.0/16, 10.42.0.0/24) is not equal to previous one (0.0.0.0/0, 0.0.0.0/0), trying to recycle old iptables rules machine # [ 31.252059] k3s[835]: I0913 15:16:43.169901 835 kube.go:558] Creating the node lease for IPv4. This is the n.Spec.PodCIDRs: [10.42.0.0/24] machine # [ 31.291380] k3s[835]: E0913 15:16:43.209448 835 log.go:32] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"3e98f7a92a6b814555fe54c8e0f02cfabf82adbf9977d6ee62fefcae01c47e87\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" machine # [ 31.296304] k3s[835]: E0913 15:16:43.213254 835 kuberuntime_sandbox.go:71] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"3e98f7a92a6b814555fe54c8e0f02cfabf82adbf9977d6ee62fefcae01c47e87\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-c5fdd76cf-768vm" machine # [ 31.302098] k3s[835]: E0913 15:16:43.213299 835 kuberuntime_manager.go:1568] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"3e98f7a92a6b814555fe54c8e0f02cfabf82adbf9977d6ee62fefcae01c47e87\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/coredns-c5fdd76cf-768vm" machine # [ 31.307923] k3s[835]: E0913 15:16:43.213412 835 pod_workers.go:1324] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"coredns-c5fdd76cf-768vm_kube-system(c7fa4117-0e7f-496c-8354-68d774a9432f)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"coredns-c5fdd76cf-768vm_kube-system(c7fa4117-0e7f-496c-8354-68d774a9432f)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"3e98f7a92a6b814555fe54c8e0f02cfabf82adbf9977d6ee62fefcae01c47e87\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/coredns-c5fdd76cf-768vm" podUID="c7fa4117-0e7f-496c-8354-68d774a9432f" machine # [ 31.315918] (udev-worker)[1228]: Network interface NamePolicy= disabled on kernel command line. machine # [ 31.317598] k3s[835]: E0913 15:16:43.226203 835 log.go:32] "RunPodSandbox from runtime service failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"f0d9fa5e8c97aa5cb6838756164f7ebe9119209c607ad2b449506b2195277bbb\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" machine # [ 31.322709] k3s[835]: E0913 15:16:43.226254 835 kuberuntime_sandbox.go:71] "Failed to create sandbox for pod" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"f0d9fa5e8c97aa5cb6838756164f7ebe9119209c607ad2b449506b2195277bbb\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-6nlqx" machine # [ 31.328251] k3s[835]: E0913 15:16:43.226320 835 kuberuntime_manager.go:1568] "CreatePodSandbox for pod failed" err="rpc error: code = Unknown desc = failed to setup network for sandbox \"f0d9fa5e8c97aa5cb6838756164f7ebe9119209c607ad2b449506b2195277bbb\": plugin type=\"flannel\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory" pod="kube-system/helm-install-niks3-6nlqx" machine # [ 31.333928] k3s[835]: E0913 15:16:43.226407 835 pod_workers.go:1324] "Error syncing pod, skipping" err="failed to \"CreatePodSandbox\" for \"helm-install-niks3-6nlqx_kube-system(338ed778-f4f8-41b0-8078-3ebdce579742)\" with CreatePodSandboxError: \"Failed to create sandbox for pod \\\"helm-install-niks3-6nlqx_kube-system(338ed778-f4f8-41b0-8078-3ebdce579742)\\\": rpc error: code = Unknown desc = failed to setup network for sandbox \\\"f0d9fa5e8c97aa5cb6838756164f7ebe9119209c607ad2b449506b2195277bbb\\\": plugin type=\\\"flannel\\\" failed (add): loadFlannelSubnetEnv failed: open /run/flannel/subnet.env: no such file or directory\"" pod="kube-system/helm-install-niks3-6nlqx" podUID="338ed778-f4f8-41b0-8078-3ebdce579742" machine # [ 31.367296] dhcpcd[647]: flannel.1: IAID a5:20:5e:8d machine # [ 31.367470] dhcpcd[647]: flannel.1: adding address fe80::f4ea:a5ff:fe20:5e8d machine # [ 31.392339] k3s[835]: I0913 15:16:43.310373 835 iptables.go:111] Setting up masking rules machine # [ 31.419371] k3s[835]: I0913 15:16:43.337385 835 iptables.go:212] Changing default FORWARD chain policy to ACCEPT machine # [ 31.437436] k3s[835]: time="2026-09-13T15:16:43Z" level=info msg="Wrote flannel subnet file to /run/flannel/subnet.env" machine # [ 31.437720] k3s[835]: time="2026-09-13T15:16:43Z" level=info msg="Running flannel backend" machine # [ 31.438190] k3s[835]: I0913 15:16:43.355553 835 vxlan_network.go:68] watching for new subnet leases machine # [ 31.438628] k3s[835]: I0913 15:16:43.355574 835 vxlan_network.go:115] starting vxlan device watcher machine # [ 31.514469] k3s[835]: I0913 15:16:43.432507 835 iptables.go:358] bootstrap done machine # [ 31.556881] k3s[835]: I0913 15:16:43.474926 835 iptables.go:358] bootstrap done machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 32.385464] dhcpcd[647]: flannel.1: soliciting an IPv6 router machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 33.023381] dhcpcd[647]: flannel.1: soliciting a DHCP lease machine # [ 33.643962] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Started tunnel to 10.0.2.15:6443" machine # [ 33.646314] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Stopped tunnel to 127.0.0.1:6443" machine # [ 33.646523] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Connecting to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect" machine # [ 33.651842] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Proxy done" err="context canceled" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 33.652443] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Handling backend connection request [machine]" machine # [ 33.653037] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect" machine # [ 33.653798] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Remotedialer connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect" machine # [ 33.664268] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF" machine # Error from server (NotFound): namespaces "niks3" not found machine # Error from server (NotFound): namespaces "niks3" not found machine # Error from server (NotFound): namespaces "niks3" not found machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 38.025936] dhcpcd[647]: flannel.1: probing for an IPv4LL address machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 39.373251] k3s[835]: I0913 15:16:51.289889 835 kuberuntime_manager.go:2095] "Updating runtime config through cri with podcidr" CIDR="10.42.0.0/24" machine # [ 39.377605] k3s[835]: I0913 15:16:51.293327 835 kubelet_network.go:47] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="10.42.0.0/24" machine # [ 40.350494] k3s[835]: time="2026-09-13T15:16:52Z" level=info msg="Starting network policy controller version v2.6.3-k3s1, built on 1970-01-01T01:01:01Z, go1.26.7" machine # [ 40.353239] k3s[835]: I0913 15:16:52.268578 835 network_policy_controller.go:164] Starting network policy controller machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 40.770469] k3s[835]: I0913 15:16:52.688231 835 network_policy_controller.go:179] Starting network policy controller full sync goroutine machine # Error from server (NotFound): namespaces "niks3" not found machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 43.166498] dhcpcd[647]: flannel.1: using IPv4LL address 169.254.76.123 machine # [ 43.166926] dhcpcd[647]: flannel.1: adding route to 169.254.0.0/16 machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 44.388852] dhcpcd[647]: flannel.1: no IPv6 Routers available machine # [ 45.181736] cni0: port 1(veth25394c81) entered blocking state machine # [ 45.182506] cni0: port 1(veth25394c81) entered disabled state machine # [ 45.183343] veth25394c81: entered allmulticast mode machine # [ 45.184043] veth25394c81: entered promiscuous mode machine # [ 45.197755] cni0: port 1(veth25394c81) entered blocking state machine # [ 45.198371] cni0: port 1(veth25394c81) entered forwarding state machine # [ 45.095869] (udev-worker)[1578]: Network interface NamePolicy= disabled on kernel command line. machine # [ 45.100236] (udev-worker)[1580]: Network interface NamePolicy= disabled on kernel command line. machine # [ 45.133741] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount59189901.mount: Deactivated successfully. machine # [ 45.147753] dhcpcd[647]: veth25394c81: IAID ff:bb:b7:42 machine # [ 45.149025] dhcpcd[647]: veth25394c81: adding address fe80::5008:ffff:febb:b742 machine # [ 45.262290] systemd[1]: Started libcontainer container 745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573. machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 45.577789] dhcpcd[647]: veth25394c81: soliciting a DHCP lease machine # [ 46.140732] cni0: port 2(vethd0a1dbe8) entered blocking state machine # [ 46.142115] cni0: port 2(vethd0a1dbe8) entered disabled state machine # [ 46.142708] vethd0a1dbe8: entered allmulticast mode machine # [ 46.144290] vethd0a1dbe8: entered promiscuous mode machine # [ 46.163144] cni0: port 2(vethd0a1dbe8) entered blocking state machine # [ 46.163773] cni0: port 2(vethd0a1dbe8) entered forwarding state machine # [ 46.040595] dhcpcd[647]: vethd0a1dbe8: IAID 1d:af:7c:9b machine # [ 46.041902] dhcpcd[647]: vethd0a1dbe8: adding address fe80::7c0a:1dff:feaf:7c9b machine # [ 46.171815] systemd[1]: Started libcontainer container 6ce343837467d6f143c68f611ef8a0d234bc1ff22015ccc79d1d160814b6944c. machine # [ 46.305535] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount3329550324.mount: Deactivated successfully. machine # [ 46.572688] systemd[1]: Started libcontainer container 8edf2bf25400367b2fd084d66aa9f9c19f4ce0d87e6def3a7c5aa8918e5110f5. machine # Error from server (NotFound): namespaces "niks3" not found machine # [ 46.839396] dhcpcd[647]: vethd0a1dbe8: soliciting a DHCP lease machine # [ 46.908518] dhcpcd[647]: veth25394c81: soliciting an IPv6 router machine # [ 47.298465] systemd[1]: Started libcontainer container 7bacd83175a6339604995527c8020a771d82ccb926174a794110b73066cca1aa. machine # [ 47.443107] dhcpcd[647]: vethd0a1dbe8: soliciting an IPv6 router machine # [ 47.716709] k3s[835]: I0913 15:16:59.634360 835 alloc.go:329] "allocated clusterIPs" service="niks3/niks3" clusterIPs={"IPv4":"10.43.23.207"} machine # [ 47.744071] k3s[835]: I0913 15:16:59.661888 835 controller.go:667] quota admission added evaluator for: cronjobs.batch machine # [ 47.771443] systemd[1]: cri-containerd-8edf2bf25400367b2fd084d66aa9f9c19f4ce0d87e6def3a7c5aa8918e5110f5.scope: Deactivated successfully. machine # [ 47.774900] systemd[1]: cri-containerd-8edf2bf25400367b2fd084d66aa9f9c19f4ce0d87e6def3a7c5aa8918e5110f5.scope: Consumed 558ms CPU time over 1.199s wall clock time, 37.2M memory peak, 4.1M incoming IP traffic, 79.1K outgoing IP traffic. machine # [ 47.823455] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-8edf2bf25400367b2fd084d66aa9f9c19f4ce0d87e6def3a7c5aa8918e5110f5-rootfs.mount: Deactivated successfully. machine # [ 48.135382] k3s[835]: I0913 15:17:00.053343 835 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="kube-system/coredns-c5fdd76cf-768vm" podStartSLOduration=18.05332423 podStartE2EDuration="18.05332423s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-13 15:16:42 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-13 15:17:00.023835566 +0000 UTC m=+29.643458873" watchObservedRunningTime="2026-09-13 15:17:00.05332423 +0000 UTC m=+29.672947537" machine # [ 48.175439] systemd[1]: Created slice libcontainer container kubepods-besteffort-poddf8cb12e_8605_45c8_85c2_c28ea00f2ebe.slice. machine # [ 48.225481] k3s[835]: I0913 15:17:00.143201 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"s3\" (UniqueName: \"kubernetes.io/secret/df8cb12e-8605-45c8-85c2-c28ea00f2ebe-s3\") pod \"niks3-59f7d88555-55jss\" (UID: \"df8cb12e-8605-45c8-85c2-c28ea00f2ebe\") " pod="niks3/niks3-59f7d88555-55jss" machine # [ 48.225644] k3s[835]: I0913 15:17:00.143239 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"oidc\" (UniqueName: \"kubernetes.io/configmap/df8cb12e-8605-45c8-85c2-c28ea00f2ebe-oidc\") pod \"niks3-59f7d88555-55jss\" (UID: \"df8cb12e-8605-45c8-85c2-c28ea00f2ebe\") " pod="niks3/niks3-59f7d88555-55jss" machine # [ 48.226086] k3s[835]: I0913 15:17:00.143304 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/df8cb12e-8605-45c8-85c2-c28ea00f2ebe-token\") pod \"niks3-59f7d88555-55jss\" (UID: \"df8cb12e-8605-45c8-85c2-c28ea00f2ebe\") " pod="niks3/niks3-59f7d88555-55jss" machine # [ 48.226552] k3s[835]: I0913 15:17:00.143429 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-hzfzw\" (UniqueName: \"kubernetes.io/projected/df8cb12e-8605-45c8-85c2-c28ea00f2ebe-kube-api-access-hzfzw\") pod \"niks3-59f7d88555-55jss\" (UID: \"df8cb12e-8605-45c8-85c2-c28ea00f2ebe\") " pod="niks3/niks3-59f7d88555-55jss" machine # [ 48.227703] k3s[835]: I0913 15:17:00.145336 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"db\" (UniqueName: \"kubernetes.io/secret/df8cb12e-8605-45c8-85c2-c28ea00f2ebe-db\") pod \"niks3-59f7d88555-55jss\" (UID: \"df8cb12e-8605-45c8-85c2-c28ea00f2ebe\") " pod="niks3/niks3-59f7d88555-55jss" machine # [ 48.980581] cni0: port 3(veth73adb661) entered blocking state machine # [ 48.982274] cni0: port 3(veth73adb661) entered disabled state machine # [ 48.983234] veth73adb661: entered allmulticast mode machine # [ 48.984077] veth73adb661: entered promiscuous mode machine # [ 48.996153] cni0: port 3(veth73adb661) entered blocking state machine # [ 48.996737] cni0: port 3(veth73adb661) entered forwarding state machine # [ 48.924958] (udev-worker)[2020]: Network interface NamePolicy= disabled on kernel command line. machine # [ 48.974450] systemd[1]: Started libcontainer container ad378d80a00399a96028e67eab97a9a40c49c6bdbdc9b2c2ad0e5678fdaf1497. machine # [ 48.978262] dhcpcd[647]: veth73adb661: IAID 8c:a0:7d:57 machine # [ 48.978643] dhcpcd[647]: veth73adb661: adding address fe80::909d:8cff:fea0:7d57 machine # [ 49.113507] systemd[1]: cri-containerd-745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573.scope: Deactivated successfully. machine # [ 49.521306] cni0: port 1(veth25394c81) entered disabled state machine # [ 49.370510] dhcpcd[647]: veth25394c81: carrier lost machine # [ 49.523498] veth25394c81 (unregistering): left allmulticast mode machine # [ 49.524303] veth25394c81 (unregistering): left promiscuous mode machine # [ 49.525172] cni0: port 1(veth25394c81) entered disabled state machine # [ 49.416292] systemd[1]: Started libcontainer container 6b040244f348e35c0a61630e8848246d7ae5629006d1479872714d24ff7d8b1d. machine # [ 49.439226] dhcpcd[647]: veth25394c81: deleting address fe80::5008:ffff:febb:b742 machine # [ 49.512887] postgres[2182]: [2182] ERROR: relation "goose_db_version" does not exist at character 36 machine # [ 49.513121] postgres[2182]: [2182] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC machine # [ 49.522278] dhcpcd[647]: veth25394c81: removing interface machine # [ 49.537473] k3s[835]: I0913 15:17:01.455092 835 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/configmap/338ed778-f4f8-41b0-8078-3ebdce579742-content\" (UniqueName: \"kubernetes.io/configmap/338ed778-f4f8-41b0-8078-3ebdce579742-content\") pod \"338ed778-f4f8-41b0-8078-3ebdce579742\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " machine # [ 49.537853] k3s[835]: I0913 15:17:01.455194 835 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-tmp\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-tmp\") pod \"338ed778-f4f8-41b0-8078-3ebdce579742\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " machine # [ 49.538472] k3s[835]: I0913 15:17:01.455221 835 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-helm\") pod \"338ed778-f4f8-41b0-8078-3ebdce579742\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " machine # [ 49.538931] k3s[835]: I0913 15:17:01.455287 835 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-kube-api-access-kqlm2\" (UniqueName: \"kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-kube-api-access-kqlm2\") pod \"338ed778-f4f8-41b0-8078-3ebdce579742\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " machine # [ 49.548894] k3s[835]: I0913 15:17:01.455319 835 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-config\") pod \"338ed778-f4f8-41b0-8078-3ebdce579742\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " machine # [ 49.549473] k3s[835]: I0913 15:17:01.455360 835 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-cache\") pod \"338ed778-f4f8-41b0-8078-3ebdce579742\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " machine # [ 49.549909] k3s[835]: I0913 15:17:01.455386 835 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-values\" (UniqueName: \"kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-values\") pod \"338ed778-f4f8-41b0-8078-3ebdce579742\" (UID: \"338ed778-f4f8-41b0-8078-3ebdce579742\") " machine # [ 49.551514] k3s[835]: I0913 15:17:01.469391 835 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/configmap/338ed778-f4f8-41b0-8078-3ebdce579742-content" pod "338ed778-f4f8-41b0-8078-3ebdce579742" (UID: "338ed778-f4f8-41b0-8078-3ebdce579742"). InnerVolumeSpecName "content". PluginName "kubernetes.io/configmap", VolumeGIDValue "" machine # [ 49.578081] k3s[835]: I0913 15:17:01.496014 835 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-values" pod "338ed778-f4f8-41b0-8078-3ebdce579742" (UID: "338ed778-f4f8-41b0-8078-3ebdce579742"). InnerVolumeSpecName "values". PluginName "kubernetes.io/projected", VolumeGIDValue "" machine # [ 49.587542] k3s[835]: I0913 15:17:01.504437 835 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-tmp" pod "338ed778-f4f8-41b0-8078-3ebdce579742" (UID: "338ed778-f4f8-41b0-8078-3ebdce579742"). InnerVolumeSpecName "tmp". PluginName "kubernetes.io/empty-dir", VolumeGIDValue "" machine # [ 49.588531] k3s[835]: I0913 15:17:01.506569 835 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-cache" pod "338ed778-f4f8-41b0-8078-3ebdce579742" (UID: "338ed778-f4f8-41b0-8078-3ebdce579742"). InnerVolumeSpecName "klipper-cache". PluginName "kubernetes.io/empty-dir", VolumeGIDValue "" machine # [ 49.589973] k3s[835]: I0913 15:17:01.507998 835 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-helm" pod "338ed778-f4f8-41b0-8078-3ebdce579742" (UID: "338ed778-f4f8-41b0-8078-3ebdce579742"). InnerVolumeSpecName "klipper-helm". PluginName "kubernetes.io/empty-dir", VolumeGIDValue "" machine # [ 49.606714] k3s[835]: I0913 15:17:01.524773 835 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-config" pod "338ed778-f4f8-41b0-8078-3ebdce579742" (UID: "338ed778-f4f8-41b0-8078-3ebdce579742"). InnerVolumeSpecName "klipper-config". PluginName "kubernetes.io/empty-dir", VolumeGIDValue "" machine # [ 49.609199] k3s[835]: I0913 15:17:01.527244 835 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-kube-api-access-kqlm2" pod "338ed778-f4f8-41b0-8078-3ebdce579742" (UID: "338ed778-f4f8-41b0-8078-3ebdce579742"). InnerVolumeSpecName "kube-api-access-kqlm2". PluginName "kubernetes.io/projected", VolumeGIDValue "" machine # [ 49.638184] k3s[835]: I0913 15:17:01.555969 835 reconciler_common.go:299] "Volume detached for volume \"klipper-config\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-config\") on node \"machine\" DevicePath \"\"" machine # [ 49.638471] k3s[835]: I0913 15:17:01.556456 835 reconciler_common.go:299] "Volume detached for volume \"klipper-cache\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-cache\") on node \"machine\" DevicePath \"\"" machine # [ 49.639859] k3s[835]: I0913 15:17:01.556475 835 reconciler_common.go:299] "Volume detached for volume \"values\" (UniqueName: \"kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-values\") on node \"machine\" DevicePath \"\"" machine # [ 49.641026] k3s[835]: I0913 15:17:01.556880 835 reconciler_common.go:299] "Volume detached for volume \"content\" (UniqueName: \"kubernetes.io/configmap/338ed778-f4f8-41b0-8078-3ebdce579742-content\") on node \"machine\" DevicePath \"\"" machine # [ 49.642301] k3s[835]: I0913 15:17:01.556899 835 reconciler_common.go:299] "Volume detached for volume \"tmp\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-tmp\") on node \"machine\" DevicePath \"\"" machine # [ 49.643230] k3s[835]: I0913 15:17:01.556911 835 reconciler_common.go:299] "Volume detached for volume \"klipper-helm\" (UniqueName: \"kubernetes.io/empty-dir/338ed778-f4f8-41b0-8078-3ebdce579742-klipper-helm\") on node \"machine\" DevicePath \"\"" machine # [ 49.644188] k3s[835]: I0913 15:17:01.556956 835 reconciler_common.go:299] "Volume detached for volume \"kube-api-access-kqlm2\" (UniqueName: \"kubernetes.io/projected/338ed778-f4f8-41b0-8078-3ebdce579742-kube-api-access-kqlm2\") on node \"machine\" DevicePath \"\"" machine # [ 49.664678] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573-rootfs.mount: Deactivated successfully. machine # [ 49.665122] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573-shm.mount: Deactivated successfully. machine # [ 49.665786] systemd[1]: run-netns-cni\x2dccffcf46\x2dced9\x2dea60\x2d3a20\x2d5a7fae535872.mount: Deactivated successfully. machine # [ 49.667791] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eprojected-kube\x2dapi\x2daccess\x2dkqlm2.mount: Deactivated successfully. machine # [ 49.668552] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eprojected-values.mount: Deactivated successfully. machine # [ 49.668953] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dcache.mount: Deactivated successfully. machine # [ 49.669583] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dhelm.mount: Deactivated successfully. machine # [ 49.669983] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eempty\x2ddir-tmp.mount: Deactivated successfully. machine # [ 49.672104] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dconfig.mount: Deactivated successfully. machine # [ 49.852500] dhcpcd[647]: veth73adb661: soliciting a DHCP lease machine # [ 50.124748] k3s[835]: I0913 15:17:02.042749 835 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573" machine # [ 50.133287] systemd[1]: Removed slice libcontainer container kubepods-burstable-pod338ed778_f4f8_41b0_8078_3ebdce579742.slice. machine # [ 50.137378] systemd[1]: kubepods-burstable-pod338ed778_f4f8_41b0_8078_3ebdce579742.slice: Consumed 589ms CPU time over 19.373s wall clock time, 37.7M memory peak, 4.1M incoming IP traffic, 79.1K outgoing IP traffic. machine # [ 50.354621] dhcpcd[647]: veth73adb661: soliciting an IPv6 router machine # [ 50.455149] k3s[835]: I0913 15:17:02.373015 835 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/niks3-59f7d88555-55jss" podStartSLOduration=2.372994188 podStartE2EDuration="2.372994188s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-13 15:17:00 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-13 15:17:02.065878619 +0000 UTC m=+31.685504999" watchObservedRunningTime="2026-09-13 15:17:02.372994188 +0000 UTC m=+31.992617495" machine # [ 51.840499] dhcpcd[647]: vethd0a1dbe8: probing for an IPv4LL address machine: (finished: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s, in 29.34 seconds) machine: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true machine: (finished: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true, in 0.19 seconds) machine: waiting for success: curl -sf http://localhost:30051/readyz | grep OK machine: (finished: waiting for success: curl -sf http://localhost:30051/readyz | grep OK, in 0.10 seconds) (finished: subtest: chart deploys and becomes ready, in 29.62 seconds) machine: waiting for success: kubectl -n ci get sa builder machine: (finished: waiting for success: kubectl -n ci get sa builder, in 0.22 seconds) machine: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt machine # [ 54.853824] dhcpcd[647]: veth73adb661: probing for an IPv4LL address machine: (finished: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt, in 0.22 seconds) machine: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt machine: (finished: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt, in 0.20 seconds) machine: must succeed: readlink -f /run/current-system/sw/bin/niks3 machine: (finished: must succeed: readlink -f /run/current-system/sw/bin/niks3, in 0.04 seconds) subtest: allowed service account can push via workload identity machine: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/69rx9yid472ww68bbf95nndvq8zi96ws-niks3-1.11.0 2>&1 machine # [ 56.932145] dhcpcd[647]: vethd0a1dbe8: using IPv4LL address 169.254.247.12 machine # [ 56.933747] dhcpcd[647]: vethd0a1dbe8: adding route to 169.254.0.0/16 machine: (finished: must succeed: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/builder.jwt niks3 push /nix/store/69rx9yid472ww68bbf95nndvq8zi96ws-niks3-1.11.0 2>&1, in 2.06 seconds) machine: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/69rx9yid472ww68bbf95nndvq8zi96ws.narinfo machine: (finished: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/69rx9yid472ww68bbf95nndvq8zi96ws.narinfo, in 0.05 seconds) (finished: subtest: allowed service account can push via workload identity, in 2.12 seconds) subtest: write scope does not grant admin machine: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status machine: (finished: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status, in 0.06 seconds) (finished: subtest: write scope does not grant admin, in 0.07 seconds) subtest: other service accounts are rejected machine: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/69rx9yid472ww68bbf95nndvq8zi96ws-niks3-1.11.0 2>&1 machine: (finished: must fail: NIKS3_SERVER_URL=http://localhost:30051 NIKS3_AUTH_TOKEN_FILE=/tmp/intruder.jwt niks3 push /nix/store/69rx9yid472ww68bbf95nndvq8zi96ws-niks3-1.11.0 2>&1, in 0.23 seconds) (finished: subtest: other service accounts are rejected, in 0.23 seconds) subtest: gc cronjob runs against the service machine: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual machine: (finished: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual, in 0.20 seconds) machine: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s machine # [ 57.827323] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod5d9078a5_20d7_430c_8f80_f59e5ea8999e.slice. machine # [ 57.916926] k3s[835]: I0913 15:17:09.834548 835 reconciler_common.go:251] "operationExecutor.VerifyControllerAttachedVolume started for volume \"token\" (UniqueName: \"kubernetes.io/secret/5d9078a5-20d7-430c-8f80-f59e5ea8999e-token\") pod \"gc-manual-vkjqz\" (UID: \"5d9078a5-20d7-430c-8f80-f59e5ea8999e\") " pod="niks3/gc-manual-vkjqz" machine # [ 58.337740] cni0: port 1(veth54666bbd) entered blocking state machine # [ 58.338555] cni0: port 1(veth54666bbd) entered disabled state machine # [ 58.339578] veth54666bbd: entered allmulticast mode machine # [ 58.340359] veth54666bbd: entered promiscuous mode machine # [ 58.350896] cni0: port 1(veth54666bbd) entered blocking state machine # [ 58.351518] cni0: port 1(veth54666bbd) entered forwarding state machine # [ 58.283601] (udev-worker)[2495]: Network interface NamePolicy= disabled on kernel command line. machine # [ 58.329644] systemd[1]: Started libcontainer container 743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e. machine # [ 58.344371] dhcpcd[647]: veth54666bbd: IAID 0e:da:21:35 machine # [ 58.344789] dhcpcd[647]: veth54666bbd: adding address fe80::a090:eff:feda:2135 machine # [ 58.459480] systemd[1]: Started libcontainer container 4d7c86d30df82ad592449aec4b6d0c195e79ad7fea9e5a0f1034c7e59f002337. machine # [ 59.165907] k3s[835]: I0913 15:17:11.083292 835 pod_startup_latency_tracker.go:148] "Observed pod startup duration" pod="niks3/gc-manual-vkjqz" podStartSLOduration=2.083130531 podStartE2EDuration="2.083130531s" totalImagesPullingTime="0s" totalInitContainerRuntime="0s" isStatefulPod=false podCreationTimestamp="2026-09-13 15:17:09 +0000 UTC" imagePullSessionsCount=0 imagePullSessionsStartsCount=0 observedRunningTime="2026-09-13 15:17:11.080449464 +0000 UTC m=+40.700077520" watchObservedRunningTime="2026-09-13 15:17:11.083130531 +0000 UTC m=+40.702842676" machine # [ 59.183315] dhcpcd[647]: veth54666bbd: soliciting a DHCP lease machine # [ 59.446202] dhcpcd[647]: vethd0a1dbe8: no IPv6 Routers available machine # [ 59.912825] dhcpcd[647]: veth73adb661: using IPv4LL address 169.254.119.184 machine # [ 59.916317] dhcpcd[647]: veth73adb661: adding route to 169.254.0.0/16 machine # [ 60.536711] systemd[1]: cri-containerd-4d7c86d30df82ad592449aec4b6d0c195e79ad7fea9e5a0f1034c7e59f002337.scope: Deactivated successfully. machine # [ 60.540999] systemd[1]: cri-containerd-4d7c86d30df82ad592449aec4b6d0c195e79ad7fea9e5a0f1034c7e59f002337.scope: Consumed 36ms CPU time over 2.075s wall clock time, 4.1M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic. machine # [ 60.575619] dhcpcd[647]: veth54666bbd: soliciting an IPv6 router machine # [ 60.607959] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-4d7c86d30df82ad592449aec4b6d0c195e79ad7fea9e5a0f1034c7e59f002337-rootfs.mount: Deactivated successfully. machine # [ 62.197660] systemd[1]: cri-containerd-743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e.scope: Deactivated successfully. machine # [ 62.250296] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e-rootfs.mount: Deactivated successfully. machine # [ 62.287178] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e-shm.mount: Deactivated successfully. machine # [ 62.501187] cni0: port 1(veth54666bbd) entered disabled state machine # [ 62.350625] dhcpcd[647]: veth54666bbd: carrier lost machine # [ 62.503754] veth54666bbd (unregistering): left allmulticast mode machine # [ 62.504587] veth54666bbd (unregistering): left promiscuous mode machine # [ 62.505595] cni0: port 1(veth54666bbd) entered disabled state machine # [ 62.376425] systemd[1]: run-netns-cni\x2d7bdec847\x2d01cf\x2d0264\x2d364b\x2de25b11663dd9.mount: Deactivated successfully. machine # [ 62.417100] dhcpcd[647]: veth54666bbd: deleting address fe80::a090:eff:feda:2135 machine # [ 62.487252] dhcpcd[647]: veth73adb661: no IPv6 Routers available machine # [ 62.487444] dhcpcd[647]: veth54666bbd: removing interface machine # [ 62.563365] k3s[835]: I0913 15:17:14.481094 835 reconciler_common.go:163] "operationExecutor.UnmountVolume started for volume \"kubernetes.io/secret/5d9078a5-20d7-430c-8f80-f59e5ea8999e-token\" (UniqueName: \"kubernetes.io/secret/5d9078a5-20d7-430c-8f80-f59e5ea8999e-token\") pod \"5d9078a5-20d7-430c-8f80-f59e5ea8999e\" (UID: \"5d9078a5-20d7-430c-8f80-f59e5ea8999e\") " machine # [ 62.575945] k3s[835]: I0913 15:17:14.494007 835 operation_generator.go:780] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/5d9078a5-20d7-430c-8f80-f59e5ea8999e-token" pod "5d9078a5-20d7-430c-8f80-f59e5ea8999e" (UID: "5d9078a5-20d7-430c-8f80-f59e5ea8999e"). InnerVolumeSpecName "token". PluginName "kubernetes.io/secret", VolumeGIDValue "" machine # [ 62.576767] systemd[1]: var-lib-kubelet-pods-5d9078a5\x2d20d7\x2d430c\x2d8f80\x2df59e5ea8999e-volumes-kubernetes.io\x7esecret-token.mount: Deactivated successfully. machine # [ 62.663468] k3s[835]: I0913 15:17:14.581506 835 reconciler_common.go:299] "Volume detached for volume \"token\" (UniqueName: \"kubernetes.io/secret/5d9078a5-20d7-430c-8f80-f59e5ea8999e-token\") on node \"machine\" DevicePath \"\"" machine # [ 62.974268] systemd[1]: Removed slice libcontainer container kubepods-besteffort-pod5d9078a5_20d7_430c_8f80_f59e5ea8999e.slice. machine # [ 62.974809] systemd[1]: kubepods-besteffort-pod5d9078a5_20d7_430c_8f80_f59e5ea8999e.slice: Consumed 68ms CPU time over 5.145s wall clock time, 4.6M memory peak, 1.5K incoming IP traffic, 987B outgoing IP traffic. machine # [ 63.171885] k3s[835]: I0913 15:17:15.089816 835 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e" machine: (finished: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s, in 5.45 seconds) (finished: subtest: gc cronjob runs against the service, in 5.65 seconds) subtest: helm test hook passes machine: must succeed: helm test -n niks3 niks3 --timeout 2m >&2 machine # [ 64.332291] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod04539781_8855_49af_a880_e41013701b38.slice. machine # [ 64.525904] cni0: port 1(vethc5645dd1) entered blocking state machine # [ 64.527317] cni0: port 1(vethc5645dd1) entered disabled state machine # [ 64.528456] vethc5645dd1: entered allmulticast mode machine # [ 64.529386] vethc5645dd1: entered promiscuous mode machine # [ 64.380044] (udev-worker)[2709]: Network interface NamePolicy= disabled on kernel command line. machine # [ 64.542536] cni0: port 1(vethc5645dd1) entered blocking state machine # [ 64.543212] cni0: port 1(vethc5645dd1) entered forwarding state machine # [ 64.431762] dhcpcd[647]: vethc5645dd1: IAID 16:24:fd:46 machine # [ 64.432334] dhcpcd[647]: vethc5645dd1: adding address fe80::1c63:16ff:fe24:fd46 machine # [ 64.513638] systemd[1]: Started libcontainer container afce97550946933590e817b3420e406d2924fd2175a44a1000c408299b80f549. machine # [ 64.630314] systemd[1]: Started libcontainer container 2341817c905e0c75dc98399ffc9440d28a40c8803cf99d484076bc35ea1759dd. machine # [ 64.699179] systemd[1]: cri-containerd-2341817c905e0c75dc98399ffc9440d28a40c8803cf99d484076bc35ea1759dd.scope: Deactivated successfully. machine # [ 64.699579] systemd[1]: cri-containerd-2341817c905e0c75dc98399ffc9440d28a40c8803cf99d484076bc35ea1759dd.scope: Consumed 31ms CPU time over 68ms wall clock time, 4.6M memory peak, 641B incoming IP traffic, 547B outgoing IP traffic. machine # [ 65.347834] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-2341817c905e0c75dc98399ffc9440d28a40c8803cf99d484076bc35ea1759dd-rootfs.mount: Deactivated successfully. machine # [ 65.367643] dhcpcd[647]: vethc5645dd1: soliciting a DHCP lease machine # [ 66.019356] dhcpcd[647]: vethc5645dd1: soliciting an IPv6 router machine # [ 66.207088] systemd[1]: cri-containerd-afce97550946933590e817b3420e406d2924fd2175a44a1000c408299b80f549.scope: Deactivated successfully. machine # [ 66.265299] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-afce97550946933590e817b3420e406d2924fd2175a44a1000c408299b80f549-rootfs.mount: Deactivated successfully. machine # [ 66.302354] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-afce97550946933590e817b3420e406d2924fd2175a44a1000c408299b80f549-shm.mount: Deactivated successfully. machine # [ 66.515608] cni0: port 1(vethc5645dd1) entered disabled state machine # [ 66.364745] dhcpcd[647]: vethc5645dd1: carrier lost machine # [ 66.517501] vethc5645dd1 (unregistering): left allmulticast mode machine # [ 66.518559] vethc5645dd1 (unregistering): left promiscuous mode machine # [ 66.519690] cni0: port 1(vethc5645dd1) entered disabled state machine # [ 66.388110] systemd[1]: run-netns-cni\x2d64cac022\x2dae18\x2dfed4\x2dac8a\x2d5cb0d43e5db2.mount: Deactivated successfully. machine # [ 66.437395] dhcpcd[647]: vethc5645dd1: deleting address fe80::1c63:16ff:fe24:fd46 machine # NAME: niks3 machine # LAST DEPLOYED: Sun Sep 13 15:16:59 2026 machine # NAMESPACE: niks3 machine # STATUS: deployed machine # REVISION: 1 machine # DESCRIPTION: Install complete machine # TEST SUITE: niks3-test machine # Last Started: Sun Sep 13 15:17:16 2026 machine # Last Completed: Sun Sep 13 15:17:18 2026 machine # Phase: Succeeded machine: (finished: must succeed: helm test -n niks3 niks3 --timeout 2m >&2, in 3.20 seconds) (finished: subtest: helm test hook passes, in 3.20 seconds) (finished: run the VM test script, in 67.33 seconds) test script finished in 67.38s cleanup kill QemuMachine (pid 45) machine # qemu-system-x86_64: terminating on signal 15 from pid 39 (/nix/store/b5bpi6zfajzzrwwpgba2q6li3nnya4bs-python3-3.14.7/bin/python3.14) (finished: cleanup, in 0.72 seconds) additionally exposed symbols: machine, vlan1, start_all, test_script, machines, machines_qemu, machines_nspawn, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, BaseMachine, QemuMachine, NspawnMachine, t, debug, dump_machine_ssh time=2026-09-13T15:17:07.552Z level=INFO msg="Uploading 8 paths to localhost (0 already cached)" time=2026-09-13T15:17:07.555Z level=INFO msg="Uploading h6q94p1jw42irzqybm1049fmxakh8701-mailcap-2.1.54 (116.6KB)" time=2026-09-13T15:17:07.555Z level=INFO msg="Uploading n51dhmdbik1kfrsm62j5knavmigwrl1a-glibc-2.42-84 (33.4MB)" time=2026-09-13T15:17:07.556Z level=INFO msg="Uploading 69rx9yid472ww68bbf95nndvq8zi96ws-niks3-1.11.0 (7.7MB)" time=2026-09-13T15:17:07.556Z level=INFO msg="Uploading ssvq1r0xd8f7paf6zqgpfql1a4drwhy2-xgcc-15.3.0-libgcc (193.0KB)" time=2026-09-13T15:17:07.557Z level=INFO msg="Uploading yh8rykx8wakl1ccn8rc351f6r2wbg4cn-libunistring-1.4.2 (2.0MB)" time=2026-09-13T15:17:07.557Z level=INFO msg="Uploading p0ff33dca0fbkskqwrl3spvxcn5974h0-tzdata-2026c (2.0MB)" time=2026-09-13T15:17:07.557Z level=INFO msg="Uploading nb6fq3nrjmyx9f9syrfnmsyfhx1ks9vg-iana-etc-20251215 (557.8KB)" time=2026-09-13T15:17:07.560Z level=INFO msg="Uploading nga9d6m9iplygw3iqghk2g840nz7b0gy-libidn2-2.3.8 (359.5KB)" time=2026-09-13T15:17:09.113Z level=INFO msg="Uploading 8 narinfos" time=2026-09-13T15:17:09.161Z level=INFO msg="Upload complete. (1.811s)"