vm-test-run-nixos-test-k3s
checks.x86_64-linux.nixos-test-k3s
· build #203
· raw
1tribuchet: building on jamie2Machine state will be reset. To keep it, pass --keep-machine-state3start all VLans4(finished: start all VLans, in 0.00 seconds)5Test will time out and terminate in 3600.0 seconds6run the VM test script7machine: waiting for unit k3s.service8machine: waiting for the VM to finish booting9machine: starting vm10machine: QEMU running (pid 45)11machine # Disk image does not exist, creating the virtualisation disk image...12machine # Formatting '/build/vm-state-machine/tmp.YFR00T96mb', fmt=raw size=858993459213machine # mke2fs 1.47.4 (6-Mar-2025)14machine # Discarding device blocks: 0/2097152 done15machine # Creating filesystem with 2097152 4k blocks and 524288 inodes16machine # Filesystem UUID: 7dcebace-693b-40e4-9567-e02b02c81a9217machine # Superblock backups stored on blocks:18machine # 32768, 98304, 163840, 229376, 294912, 819200, 884736, 160563219machine # 20machine # Allocating group tables: 0/64 done21machine # Writing inode tables: 0/64 done22machine # Creating journal (16384 blocks): done23machine # Writing superblocks and filesystem accounting information: 0/64 done24machine # 25machine # Virtualisation disk image created.26machine # SeaBIOS (version rel-1.17.0-0-gb52ca86e094d-prebuilt.qemu.org)27machine # 28machine # 29machine # iPXE (http://ipxe.org) 00:02.0 CA00 PCI2.10 PnP PMM+7EFCC730+7EF2C730 CA0030machine # Press Ctrl-B to configure iPXE (PCI 00:02.0)...31machine # 32machine # 33machine # 34machine # 35machine # iPXE (http://ipxe.org) 00:08.0 CB00 PCI2.10 PnP PMM 7EFCC730 7EF2C730 CB0036machine # Press Ctrl-B to configure iPXE (PCI 00:08.0)...37machine # 38machine # 39machine # Booting from ROM...40machine # 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 202641machine # [ 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=tty042machine # [ 0.000000] BIOS-provided physical RAM map:43machine # [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable44machine # [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved45machine # [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved46machine # [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007ffd7fff] usable47machine # [ 0.000000] BIOS-e820: [mem 0x000000007ffd8000-0x000000007fffffff] reserved48machine # [ 0.000000] BIOS-e820: [mem 0x00000000b0000000-0x00000000bfffffff] reserved49machine # [ 0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved50machine # [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved51machine # [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved52machine # [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000013fffffff] usable53machine # [ 0.000000] BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved54machine # [ 0.000000] NX (Execute Disable) protection: active55machine # [ 0.000000] APIC: Static calls initialized56machine # [ 0.000000] SMBIOS 2.8 present.57machine # [ 0.000000] DMI: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.17.0-0-gb52ca86e094d-prebuilt.qemu.org 04/01/201458machine # [ 0.000000] DMI: Memory slots populated: 1/159machine # [ 0.000000] Hypervisor detected: KVM60machine # [ 0.000000] last_pfn = 0x7ffd8 max_arch_pfn = 0x1000000000061machine # [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d0062machine # [ 0.000000] kvm-clock: using sched offset of 478398190 cycles63machine # [ 0.000002] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns64machine # [ 0.000004] tsc: Detected 2400.012 MHz processor65machine # [ 0.000812] last_pfn = 0x140000 max_arch_pfn = 0x1000000000066machine # [ 0.000838] MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs67machine # [ 0.000840] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT68machine # [ 0.000877] last_pfn = 0x7ffd8 max_arch_pfn = 0x1000000000069machine # [ 0.002740] found SMP MP-table at [mem 0x000f5450-0x000f545f]70machine # [ 0.002750] Using GB pages for direct mapping71machine # [ 0.002875] RAMDISK: [mem 0x7e36a000-0x7ffcffff]72machine # [ 0.002881] ACPI: Early table checksum verification disabled73machine # [ 0.002883] ACPI: RSDP 0x00000000000F5250 000014 (v00 BOCHS )74machine # [ 0.002887] ACPI: RSDT 0x000000007FFE247D 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)75machine # [ 0.002891] ACPI: FACP 0x000000007FFE226D 0000F4 (v03 BOCHS BXPC 00000001 BXPC 00000001)76machine # [ 0.002897] ACPI: DSDT 0x000000007FFE0040 00222D (v01 BOCHS BXPC 00000001 BXPC 00000001)77machine # [ 0.002899] ACPI: FACS 0x000000007FFE0000 00004078machine # [ 0.002900] ACPI: APIC 0x000000007FFE2361 000080 (v03 BOCHS BXPC 00000001 BXPC 00000001)79machine # [ 0.002902] ACPI: HPET 0x000000007FFE23E1 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)80machine # [ 0.002903] ACPI: MCFG 0x000000007FFE2419 00003C (v01 BOCHS BXPC 00000001 BXPC 00000001)81machine # [ 0.002905] ACPI: WAET 0x000000007FFE2455 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001)82machine # [ 0.002906] ACPI: Reserving FACP table memory at [mem 0x7ffe226d-0x7ffe2360]83machine # [ 0.002907] ACPI: Reserving DSDT table memory at [mem 0x7ffe0040-0x7ffe226c]84machine # [ 0.002908] ACPI: Reserving FACS table memory at [mem 0x7ffe0000-0x7ffe003f]85machine # [ 0.002908] ACPI: Reserving APIC table memory at [mem 0x7ffe2361-0x7ffe23e0]86machine # [ 0.002909] ACPI: Reserving HPET table memory at [mem 0x7ffe23e1-0x7ffe2418]87machine # [ 0.002909] ACPI: Reserving MCFG table memory at [mem 0x7ffe2419-0x7ffe2454]88machine # [ 0.002910] ACPI: Reserving WAET table memory at [mem 0x7ffe2455-0x7ffe247c]89machine # [ 0.003124] No NUMA configuration found90machine # [ 0.003125] Faking a node at [mem 0x0000000000000000-0x000000013fffffff]91machine # [ 0.003127] NODE_DATA(0) allocated [mem 0x13fff8780-0x13fffdcff]92machine # [ 0.005207] Zone ranges:93machine # [ 0.005208] DMA [mem 0x0000000000001000-0x0000000000ffffff]94machine # [ 0.005209] DMA32 [mem 0x0000000001000000-0x00000000ffffffff]95machine # [ 0.005210] Normal [mem 0x0000000100000000-0x000000013fffffff]96machine # [ 0.005211] Device empty97machine # [ 0.005212] Movable zone start for each node98machine # [ 0.005213] Early memory node ranges99machine # [ 0.005213] node 0: [mem 0x0000000000001000-0x000000000009efff]100machine # [ 0.005214] node 0: [mem 0x0000000000100000-0x000000007ffd7fff]101machine # [ 0.005215] node 0: [mem 0x0000000100000000-0x000000013fffffff]102machine # [ 0.005216] Initmem setup node 0 [mem 0x0000000000001000-0x000000013fffffff]103machine # [ 0.005233] On node 0, zone DMA: 1 pages in unavailable ranges104machine # [ 0.005482] On node 0, zone DMA: 97 pages in unavailable ranges105machine # [ 0.054909] On node 0, zone Normal: 40 pages in unavailable ranges106machine # [ 0.055360] ACPI: PM-Timer IO Port: 0x608107machine # [ 0.055373] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])108machine # [ 0.055398] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23109machine # [ 0.055400] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)110machine # [ 0.055402] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)111machine # [ 0.055403] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)112machine # [ 0.055404] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)113machine # [ 0.055405] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)114machine # [ 0.055408] ACPI: Using ACPI (MADT) for SMP configuration information115machine # [ 0.055409] ACPI: HPET id: 0x8086a201 base: 0xfed00000116machine # [ 0.055413] TSC deadline timer available117machine # [ 0.055417] CPU topo: Max. logical packages: 1118machine # [ 0.055418] CPU topo: Max. logical dies: 1119machine # [ 0.055418] CPU topo: Max. dies per package: 1120machine # [ 0.055421] CPU topo: Max. threads per core: 1121machine # [ 0.055422] CPU topo: Num. cores per package: 2122machine # [ 0.055423] CPU topo: Num. threads per package: 2123machine # [ 0.055423] CPU topo: Allowing 2 present CPUs plus 0 hotplug CPUs124machine # [ 0.055444] kvm-guest: APIC: eoi() replaced with kvm_guest_apic_eoi_write()125machine # [ 0.055459] kvm-guest: KVM setup pv remote TLB flush126machine # [ 0.055462] kvm-guest: setup PV sched yield127machine # [ 0.055471] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]128machine # [ 0.055472] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x000fffff]129machine # [ 0.055473] PM: hibernation: Registered nosave memory: [mem 0x7ffd8000-0xffffffff]130machine # [ 0.055475] [mem 0xc0000000-0xfed1bfff] available for PCI devices131machine # [ 0.055476] Booting paravirtualized kernel on KVM132machine # [ 0.055480] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns133machine # [ 0.059985] setup_percpu: NR_CPUS:384 nr_cpumask_bits:2 nr_cpu_ids:2 nr_node_ids:1134machine # [ 0.062015] percpu: Embedded 98 pages/cpu s278528 r8192 d114688 u1048576135machine # [ 0.062061] kvm-guest: PV spinlocks enabled136machine # [ 0.062062] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear)137machine # [ 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=tty0138machine # [ 0.062161] Unknown kernel command line parameters "regInfo=/nix/store/yil5kla6ml0bzhfrmwav86giy6vskrgd-closure-info/registration", will be passed to user space.139machine # [ 0.062174] random: crng init done140machine # [ 0.062175] printk: log buffer data + meta data: 262144 + 917504 = 1179648 bytes141machine # [ 0.066266] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)142machine # [ 0.068241] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)143machine # [ 0.068285] software IO TLB: area num 2.144machine # [ 0.135311] Fallback order for Node 0: 0145machine # [ 0.135318] Built 1 zonelists, mobility grouping on. Total pages: 786294146machine # [ 0.135320] Policy zone: Normal147machine # [ 0.137733] mem auto-init: stack:all(zero), heap alloc:on, heap free:off148machine # [ 0.142918] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1149machine # [ 0.149003] allocated 6291456 bytes of page_ext150machine # [ 0.158810] ftrace: allocating 48732 entries in 192 pages151machine # [ 0.158812] ftrace: allocated 192 pages with 2 groups152machine # [ 0.159662] Dynamic Preempt: lazy153machine # [ 0.159849] rcu: Preemptible hierarchical RCU implementation.154machine # [ 0.159850] rcu: RCU event tracing is enabled.155machine # [ 0.159851] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=2.156machine # [ 0.159852] Trampoline variant of Tasks RCU enabled.157machine # [ 0.159853] Rude variant of Tasks RCU enabled.158machine # [ 0.159853] Tracing variant of Tasks RCU enabled.159machine # [ 0.159854] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.160machine # [ 0.159854] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2161machine # [ 0.159866] RCU Tasks: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.162machine # [ 0.159868] RCU Tasks Rude: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.163machine # [ 0.159869] RCU Tasks Trace: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2.164machine # [ 0.164169] NR_IRQS: 24832, nr_irqs: 440, preallocated irqs: 16165machine # [ 0.164439] rcu: srcu_init: Setting srcu_struct sizes based on contention.166machine # [ 0.164446] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns167machine # [ 0.164556] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)168machine # [ 0.168053] Console: colour VGA+ 80x25169machine # [ 0.168056] printk: legacy console [tty0] enabled170machine # [ 0.199092] printk: legacy console [ttyS0] enabled171machine # [ 0.310734] ACPI: Core revision 20250807172machine # [ 0.311618] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns173machine # [ 0.313183] APIC: Switch to symmetric I/O mode setup174machine # [ 0.314206] x2apic enabled175machine # [ 0.314961] APIC: Switched APIC routing to: physical x2apic176machine # [ 0.315850] kvm-guest: APIC: send_IPI_mask() replaced with kvm_send_ipi_mask()177machine # [ 0.317032] kvm-guest: APIC: send_IPI_mask_allbutself() replaced with kvm_send_ipi_mask_allbutself()178machine # [ 0.318559] kvm-guest: setup PV IPIs179machine # [ 0.320124] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1180machine # [ 0.321135] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229842dd0bd, max_idle_ns: 440795319571 ns181machine # [ 0.325412] Calibrating delay loop (skipped) preset value.. 4800.02 BogoMIPS (lpj=2400012)182machine # [ 0.326494] x86/cpu: User Mode Instruction Prevention (UMIP) activated183machine # [ 0.327559] Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127184machine # [ 0.329156] Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0185machine # [ 0.330413] mitigations: Enabled attack vectors: user_kernel, user_user, guest_host, guest_guest, SMT mitigations: auto186machine # [ 0.331410] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl187machine # [ 0.333410] Transient Scheduler Attacks: Vulnerable: No microcode188machine # [ 0.334409] Spectre V2 : Mitigation: Enhanced / Automatic IBRS189machine # [ 0.335410] Speculative Return Stack Overflow: Mitigation: Safe RET190machine # [ 0.336410] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization191machine # [ 0.337416] Spectre V2 : Enabling IBPB for BPF192machine # [ 0.338976] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier193machine # [ 0.339411] active return thunk: srso_alias_return_thunk194machine # [ 0.340412] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'195machine # [ 0.341410] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'196machine # [ 0.342409] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'197machine # [ 0.343410] x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask'198machine # [ 0.344409] x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256'199machine # [ 0.345410] x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256'200machine # [ 0.346409] x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers'201machine # [ 0.348410] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256202machine # [ 0.349409] x86/fpu: xstate_offset[5]: 832, xstate_sizes[5]: 64203machine # [ 0.350409] x86/fpu: xstate_offset[6]: 896, xstate_sizes[6]: 512204machine # [ 0.351409] x86/fpu: xstate_offset[7]: 1408, xstate_sizes[7]: 1024205machine # [ 0.352410] x86/fpu: xstate_offset[9]: 2432, xstate_sizes[9]: 8206machine # [ 0.353410] x86/fpu: Enabled xstate features 0x2e7, context size is 2440 bytes, using 'compacted' format.207machine # [ 0.383080] Freeing SMP alternatives memory: 44K208machine # [ 0.383412] pid_max: default: 32768 minimum: 301209machine # [ 0.384501] LSM: initializing lsm=capability,landlock,yama,bpf,ima210machine # [ 0.385508] landlock: Up and running.211machine # [ 0.386410] Yama: becoming mindful.212machine # [ 0.387517] LSM support for eBPF active213machine # [ 0.388338] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)214machine # [ 0.389474] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)215machine # [ 0.392045] smpboot: CPU0: AMD EPYC 9654 96-Core Processor (family: 0x19, model: 0x11, stepping: 0x1)216machine # [ 0.392935] Performance Events: Fam17h+ core perfctr, AMD PMU driver.217machine # [ 0.393415] ... version: 2218machine # [ 0.394126] ... bit width: 48219machine # [ 0.394412] ... generic counters: 6220machine # [ 0.395174] ... generic bitmap: 000000000000003f221machine # [ 0.395423] ... fixed-purpose counters: 0222machine # [ 0.396153] ... fixed-purpose bitmap: 0000000000000000223machine # [ 0.396412] ... value mask: 0000ffffffffffff224machine # [ 0.397374] ... max period: 00007fffffffffff225machine # [ 0.398144] ... global_ctrl mask: 000000000000003f226machine # [ 0.398532] signal: max sigframe size: 3376227machine # [ 0.399372] rcu: Hierarchical SRCU implementation.228machine # [ 0.400052] rcu: Max phase no-delay instances is 400.229machine # [ 0.400586] Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level230machine # [ 0.405872] smp: Bringing up secondary CPUs ...231machine # [ 0.406724] smpboot: x86: Booting SMP configuration:232machine # [ 0.407415] .... node #0, CPUs: #1233machine # [ 0.408449] smp: Brought up 1 node, 2 CPUs234machine # [ 0.409934] smpboot: Total of 2 processors activated (9600.04 BogoMIPS)235machine # [ 0.410712] Memory: 2928724K/3145176K available (17215K kernel code, 2726K rwdata, 13584K rodata, 3644K init, 2988K bss, 203700K reserved, 0K cma-reserved)236machine # [ 0.412414] devtmpfs: initialized237machine # [ 0.413536] x86/mm: Memory block size: 128MB238machine # [ 0.416483] posixtimers hash table entries: 1024 (order: 2, 16384 bytes, linear)239machine # [ 0.417450] futex hash table entries: 512 (32768 bytes on 1 NUMA nodes, total 32 KiB, linear).240machine # [ 0.418509] pinctrl core: initialized pinctrl subsystem241machine # [ 0.419734] PM: RTC time: 15:16:11, date: 2026-09-13242machine # [ 0.423108] NET: Registered PF_NETLINK/PF_ROUTE protocol family243machine # [ 0.424154] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations244machine # [ 0.424440] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations245machine # [ 0.425930] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations246machine # [ 0.426422] audit: initializing netlink subsys (disabled)247machine # [ 0.427439] audit: type=2000 audit(1789312572.010:1): state=initialized audit_enabled=0 res=1248machine # [ 0.427666] thermal_sys: Registered thermal governor 'fair_share'249machine # [ 0.428415] thermal_sys: Registered thermal governor 'bang_bang'250machine # [ 0.429412] thermal_sys: Registered thermal governor 'step_wise'251machine # [ 0.430413] thermal_sys: Registered thermal governor 'user_space'252machine # [ 0.431412] thermal_sys: Registered thermal governor 'power_allocator'253machine # [ 0.432428] cpuidle: using governor menu254machine # [ 0.434607] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5255machine # [ 0.435656] PCI: ECAM [mem 0xb0000000-0xbfffffff] (base 0xb0000000) for domain 0000 [bus 00-ff]256machine # [ 0.436417] PCI: ECAM [mem 0xb0000000-0xbfffffff] reserved as E820 entry257machine # [ 0.437424] PCI: Using configuration type 1 for base access258machine # [ 0.438594] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.259machine # [ 0.445478] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages260machine # [ 0.449413] HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page261machine # [ 0.450413] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages262machine # [ 0.451413] HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page263machine # [ 0.466414] ACPI: Added _OSI(Module Device)264machine # [ 0.468421] ACPI: Added _OSI(Processor Device)265machine # [ 0.469419] ACPI: Added _OSI(Processor Aggregator Device)266machine # [ 0.478879] ACPI: 1 ACPI AML tables successfully acquired and loaded267machine # [ 0.483918] ACPI: Interpreter enabled268machine # [ 0.485485] ACPI: PM: (supports S0 S3 S4 S5)269machine # [ 0.486419] ACPI: Using IOAPIC for interrupt routing270machine # [ 0.488668] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug271machine # [ 0.492419] PCI: Using E820 reservations for host bridge windows272machine # [ 0.494790] ACPI: Enabled 2 GPEs in block 00 to 3F273machine # [ 0.504462] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])274machine # [ 0.506423] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]275machine # [ 0.509593] acpi PNP0A08:00: _OSC: platform does not support [PCIeHotplug LTR]276machine # [ 0.511674] acpi PNP0A08:00: _OSC: OS now controls [PME AER PCIeCapability]277machine # [ 0.514844] PCI host bridge to bus 0000:00278machine # [ 0.515417] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]279machine # [ 0.516413] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]280machine # [ 0.517413] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]281machine # [ 0.518412] pci_bus 0000:00: root bus resource [mem 0x80000000-0xafffffff window]282machine # [ 0.520412] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window]283machine # [ 0.521412] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe07ffffffff window]284machine # [ 0.522426] pci_bus 0000:00: root bus resource [bus 00-ff]285machine # [ 0.523525] pci 0000:00:00.0: [8086:29c0] type 00 class 0x060000 conventional PCI endpoint286machine # [ 0.525859] pci 0000:00:01.0: [1234:1111] type 00 class 0x030000 conventional PCI endpoint287machine # [ 0.534491] pci 0000:00:01.0: BAR 0 [mem 0xfd000000-0xfdffffff pref]288machine # [ 0.535424] pci 0000:00:01.0: BAR 2 [mem 0xfebd0000-0xfebd0fff]289machine # [ 0.536435] pci 0000:00:01.0: ROM [mem 0xfebc0000-0xfebcffff pref]290machine # [ 0.538606] pci 0000:00:01.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]291machine # [ 0.540125] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint292machine # [ 0.544447] pci 0000:00:02.0: BAR 0 [io 0xc140-0xc15f]293machine # [ 0.545419] pci 0000:00:02.0: BAR 1 [mem 0xfebd1000-0xfebd1fff]294machine # [ 0.546434] pci 0000:00:02.0: BAR 4 [mem 0xe0000000000-0xe0000003fff 64bit pref]295machine # [ 0.548419] pci 0000:00:02.0: ROM [mem 0xfeb40000-0xfeb7ffff pref]296machine # [ 0.549960] pci 0000:00:03.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint297machine # [ 0.553445] pci 0000:00:03.0: BAR 0 [io 0xc160-0xc17f]298machine # [ 0.554324] pci 0000:00:03.0: BAR 1 [mem 0xfebd2000-0xfebd2fff]299machine # [ 0.555212] pci 0000:00:03.0: BAR 4 [mem 0xe0000004000-0xe0000007fff 64bit pref]300machine # [ 0.556910] pci 0000:00:04.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint301machine # [ 0.560305] pci 0000:00:04.0: BAR 0 [io 0xc080-0xc0bf]302machine # [ 0.561116] pci 0000:00:04.0: BAR 1 [mem 0xfebd3000-0xfebd3fff]303machine # [ 0.562434] pci 0000:00:04.0: BAR 4 [mem 0xe0000008000-0xe000000bfff 64bit pref]304machine # [ 0.563943] pci 0000:00:05.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint305machine # [ 0.568446] pci 0000:00:05.0: BAR 0 [io 0xc180-0xc19f]306machine # [ 0.570420] pci 0000:00:05.0: BAR 1 [mem 0xfebd4000-0xfebd4fff]307machine # [ 0.571434] pci 0000:00:05.0: BAR 4 [mem 0xe000000c000-0xe000000ffff 64bit pref]308machine # [ 0.572961] pci 0000:00:06.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint309machine # [ 0.576443] pci 0000:00:06.0: BAR 0 [io 0xc1a0-0xc1bf]310machine # [ 0.577338] pci 0000:00:06.0: BAR 1 [mem 0xfebd5000-0xfebd5fff]311machine # [ 0.578226] pci 0000:00:06.0: BAR 4 [mem 0xe0000010000-0xe0000013fff 64bit pref]312machine # [ 0.580507] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint313machine # [ 0.584153] pci 0000:00:07.0: BAR 0 [io 0xc000-0xc07f]314machine # [ 0.584419] pci 0000:00:07.0: BAR 1 [mem 0xfebd6000-0xfebd6fff]315machine # [ 0.585434] pci 0000:00:07.0: BAR 4 [mem 0xe0000014000-0xe0000017fff 64bit pref]316machine # [ 0.588009] pci 0000:00:08.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint317machine # [ 0.601443] pci 0000:00:08.0: BAR 0 [io 0xc1c0-0xc1df]318machine # [ 0.603419] pci 0000:00:08.0: BAR 1 [mem 0xfebd7000-0xfebd7fff]319machine # [ 0.604433] pci 0000:00:08.0: BAR 4 [mem 0xe0000018000-0xe000001bfff 64bit pref]320machine # [ 0.605418] pci 0000:00:08.0: ROM [mem 0xfeb80000-0xfebbffff pref]321machine # [ 0.607154] pci 0000:00:09.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint322machine # [ 0.609448] pci 0000:00:09.0: BAR 1 [mem 0xfebd8000-0xfebd8fff]323machine # [ 0.610434] pci 0000:00:09.0: BAR 4 [mem 0xe000001c000-0xe000001ffff 64bit pref]324machine # [ 0.613375] pci 0000:00:0a.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint325machine # [ 0.616473] pci 0000:00:0a.0: BAR 0 [io 0xc0c0-0xc0ff]326machine # [ 0.617402] pci 0000:00:0a.0: BAR 1 [mem 0xfebd9000-0xfebd9fff]327machine # [ 0.618281] pci 0000:00:0a.0: BAR 4 [mem 0xe0000020000-0xe0000023fff 64bit pref]328machine # [ 0.619992] pci 0000:00:0b.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint329machine # [ 0.624319] pci 0000:00:0b.0: BAR 0 [io 0xc1e0-0xc1ff]330machine # [ 0.625117] pci 0000:00:0b.0: BAR 1 [mem 0xfebda000-0xfebdafff]331machine # [ 0.626434] pci 0000:00:0b.0: BAR 4 [mem 0xe0000024000-0xe0000027fff 64bit pref]332machine # [ 0.627998] pci 0000:00:1d.0: [8086:2934] type 00 class 0x0c0300 conventional PCI endpoint333machine # [ 0.630123] pci 0000:00:1d.0: BAR 4 [io 0xc200-0xc21f]334machine # [ 0.631614] pci 0000:00:1d.1: [8086:2935] type 00 class 0x0c0300 conventional PCI endpoint335machine # [ 0.633036] pci 0000:00:1d.1: BAR 4 [io 0xc220-0xc23f]336machine # [ 0.635317] pci 0000:00:1d.2: [8086:2936] type 00 class 0x0c0300 conventional PCI endpoint337machine # [ 0.637106] pci 0000:00:1d.2: BAR 4 [io 0xc240-0xc25f]338machine # [ 0.638626] pci 0000:00:1d.7: [8086:293a] type 00 class 0x0c0320 conventional PCI endpoint339machine # [ 0.639999] pci 0000:00:1d.7: BAR 0 [mem 0xfebdb000-0xfebdbfff]340machine # [ 0.641711] pci 0000:00:1f.0: [8086:2918] type 00 class 0x060100 conventional PCI endpoint341machine # [ 0.643694] pci 0000:00:1f.0: quirk: [io 0x0600-0x067f] claimed by ICH6 ACPI/GPIO/TCO342machine # [ 0.644675] pci 0000:00:1f.2: [8086:2922] type 00 class 0x010601 conventional PCI endpoint343machine # [ 0.647464] pci 0000:00:1f.2: BAR 4 [io 0xc260-0xc27f]344machine # [ 0.648377] pci 0000:00:1f.2: BAR 5 [mem 0xfebdc000-0xfebdcfff]345machine # [ 0.650514] pci 0000:00:1f.3: [8086:2930] type 00 class 0x0c0500 conventional PCI endpoint346machine # [ 0.652055] pci 0000:00:1f.3: BAR 4 [io 0x0700-0x073f]347machine # [ 0.656469] ACPI: PCI: Interrupt link LNKA configured for IRQ 10348machine # [ 0.657528] ACPI: PCI: Interrupt link LNKB configured for IRQ 10349machine # [ 0.658518] ACPI: PCI: Interrupt link LNKC configured for IRQ 11350machine # [ 0.659547] ACPI: PCI: Interrupt link LNKD configured for IRQ 11351machine # [ 0.660511] ACPI: PCI: Interrupt link LNKE configured for IRQ 10352machine # [ 0.661510] ACPI: PCI: Interrupt link LNKF configured for IRQ 10353machine # [ 0.662513] ACPI: PCI: Interrupt link LNKG configured for IRQ 11354machine # [ 0.663514] ACPI: PCI: Interrupt link LNKH configured for IRQ 11355machine # [ 0.665449] ACPI: PCI: Interrupt link GSIA configured for IRQ 16356machine # [ 0.666429] ACPI: PCI: Interrupt link GSIB configured for IRQ 17357machine # [ 0.667429] ACPI: PCI: Interrupt link GSIC configured for IRQ 18358machine # [ 0.668427] ACPI: PCI: Interrupt link GSID configured for IRQ 19359machine # [ 0.669426] ACPI: PCI: Interrupt link GSIE configured for IRQ 20360machine # [ 0.670425] ACPI: PCI: Interrupt link GSIF configured for IRQ 21361machine # [ 0.671425] ACPI: PCI: Interrupt link GSIG configured for IRQ 22362machine # [ 0.672425] ACPI: PCI: Interrupt link GSIH configured for IRQ 23363machine # [ 0.674590] iommu: Default domain type: Translated364machine # [ 0.675413] iommu: DMA domain TLB invalidation policy: lazy mode365machine # [ 0.676653] ACPI: bus type USB registered366machine # [ 0.677484] usbcore: registered new interface driver usbfs367machine # [ 0.678428] usbcore: registered new interface driver hub368machine # [ 0.679346] usbcore: registered new device driver usb369machine # [ 0.681169] NetLabel: Initializing370machine # [ 0.682414] NetLabel: domain hash size = 128371machine # [ 0.683158] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO372machine # [ 0.683493] NetLabel: unlabeled traffic allowed by default373machine # [ 0.684422] PCI: Using ACPI for IRQ routing374machine # [ 0.727572] pci 0000:00:01.0: vgaarb: setting as boot VGA device375machine # [ 0.728408] pci 0000:00:01.0: vgaarb: bridge control possible376machine # [ 0.728408] pci 0000:00:01.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none377machine # [ 0.731421] vgaarb: loaded378machine # [ 0.732173] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0379machine # [ 0.732413] hpet0: 3 comparators, 64-bit 100.000000 MHz counter380machine # [ 0.738491] clocksource: Switched to clocksource kvm-clock381machine # [ 0.742211] VFS: Disk quotas dquot_6.6.0382machine # [ 0.742922] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)383machine # [ 0.744372] pnp: PnP ACPI init384machine # [ 0.745199] ACPI: IRQ 4 override to edge(!), high(!)385machine # [ 0.746213] system 00:05: [mem 0xb0000000-0xbfffffff window] has been reserved386machine # [ 0.747829] pnp: PnP ACPI: found 6 devices387machine # [ 0.755482] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns388machine # [ 0.757007] clocksource: Switched to clocksource acpi_pm389machine # [ 0.758038] NET: Registered PF_INET protocol family390machine # [ 0.759468] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)391machine # [ 0.775726] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)392machine # [ 0.777344] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)393machine # [ 0.778742] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)394machine # [ 0.781196] TCP bind hash table entries: 32768 (order: 8, 1048576 bytes, linear)395machine # [ 0.782517] TCP: Hash tables configured (established 32768 bind 32768)396machine # [ 0.783689] MPTCP token hash table entries: 4096 (order: 5, 98304 bytes, linear)397machine # [ 0.785037] UDP hash table entries: 2048 (order: 5, 131072 bytes, linear)398machine # [ 0.786175] UDP-Lite hash table entries: 2048 (order: 5, 131072 bytes, linear)399machine # [ 0.787579] NET: Registered PF_UNIX/PF_LOCAL protocol family400machine # [ 0.788598] NET: Registered PF_XDP protocol family401machine # [ 0.789482] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]402machine # [ 0.790540] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]403machine # [ 0.791598] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]404machine # [ 0.792746] pci_bus 0000:00: resource 7 [mem 0x80000000-0xafffffff window]405machine # [ 0.793899] pci_bus 0000:00: resource 8 [mem 0xc0000000-0xfebfffff window]406machine # [ 0.795073] pci_bus 0000:00: resource 9 [mem 0xe0000000000-0xe07ffffffff window]407machine # [ 0.796944] ACPI: \_SB_.GSIA: Enabled at IRQ 16408machine # [ 0.799053] ACPI: \_SB_.GSIB: Enabled at IRQ 17409machine # [ 0.801043] ACPI: \_SB_.GSIC: Enabled at IRQ 18410machine # [ 0.803251] ACPI: \_SB_.GSID: Enabled at IRQ 19411machine # [ 0.804942] PCI: CLS 0 bytes, default 64412machine # [ 0.805792] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)413machine # [ 0.806029] Trying to unpack rootfs image as initramfs...414machine # [ 0.806880] software IO TLB: mapped [mem 0x000000007a36a000-0x000000007e36a000] (64MB)415machine # [ 0.809342] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229842dd0bd, max_idle_ns: 440795319571 ns416machine # [ 0.829822] Initialise system trusted keyrings417machine # [ 0.830792] workingset: timestamp_bits=40 max_order=20 bucket_order=0418machine # [ 0.841912] Key type asymmetric registered419machine # [ 0.842680] Asymmetric key parser 'x509' registered420machine # [ 0.843603] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)421machine # [ 0.845027] io scheduler mq-deadline registered422machine # [ 0.845831] io scheduler kyber registered423machine # [ 0.850346] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled424machine # [ 0.851650] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A425machine # [ 0.853790] Linux agpgart interface v0.103426machine # [ 0.854627] ACPI: bus type drm_connector registered427machine # [ 0.856354] usbcore: registered new interface driver usbserial_generic428machine # [ 0.857470] usbserial: USB Serial support registered for generic429machine # [ 0.858492] amd_pstate: The CPPC feature is supported but currently disabled by the BIOS.430machine # [ 0.858492] Please enable it if your BIOS has the CPPC option.431machine # [ 0.860814] amd_pstate: the _CPC object is not present in SBIOS or ACPI disabled432machine # [ 0.862262] drop_monitor: Initializing network drop monitor service433machine # [ 0.863477] NET: Registered PF_INET6 protocol family434machine # [ 0.866181] Segment Routing with IPv6435machine # [ 0.866891] In-situ OAM (IOAM) with IPv6436machine # [ 0.869254] IPI shorthand broadcast: enabled437machine # [ 0.873540] sched_clock: Marking stable (721013595, 151963125)->(893958870, -20982150)438machine # [ 0.875298] registered taskstats version 1439machine # [ 0.876325] Loading compiled-in X.509 certificates440machine # [ 0.886008] Demotion targets for Node 0: null441machine # [ 0.887099] Key type .fscrypt registered442machine # [ 0.887777] Key type fscrypt-provisioning registered443machine # [ 0.888791] ima: No TPM chip found, activating TPM-bypass!444machine # [ 0.889758] ima: Allocated hash algorithm: sha1445machine # [ 0.890617] ima: No architecture policies found446machine # [ 0.891658] PM: Magic number: 10:306:285447machine # [ 0.894498] RAS: Correctable Errors collector initialized.448machine # [ 0.899002] clk: Disabling unused clocks449machine # [ 0.899724] PM: genpd: Disabling unused power domains450machine # [ 1.056347] Freeing initrd memory: 29080K451machine # [ 1.059667] Freeing unused decrypted memory: 2028K452machine # [ 1.062324] Freeing unused kernel image (initmem) memory: 3644K453machine # [ 1.063454] Write protecting the kernel read-only data: 32768k454machine # [ 1.065450] Freeing unused kernel image (text/rodata gap) memory: 1216K455machine # [ 1.067024] Freeing unused kernel image (rodata/data gap) memory: 752K456machine # [ 1.118252] x86/mm: Checked W+X mappings: passed, no W+X pages found.457machine # [ 1.119393] Run /init as init process458machine # [ 1.131106] systemd[1]: Inserted module 'autofs4'459machine # [ 1.153263] fuse: init (API version 7.45)460machine # [ 1.160519] ACPI: \_SB_.GSIG: Enabled at IRQ 22461machine # [ 1.163399] ACPI: \_SB_.GSIH: Enabled at IRQ 23462machine # [ 1.167422] ACPI: \_SB_.GSIE: Enabled at IRQ 20463machine # [ 1.172846] ACPI: \_SB_.GSIF: Enabled at IRQ 21464machine # [ 1.236188] systemd[1]: Successfully made /usr/ read-only.465machine # [ 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)466machine # [ 1.576747] systemd[1]: Detected virtualization kvm.467machine # [ 1.577649] systemd[1]: Detected architecture x86-64.468machine # [ 1.578553] systemd[1]: Running in initrd.469machine # [ 1.579660] systemd[1]: Initializing machine ID from random generator.470machine # [ 1.580893] systemd[1]: Hostname set to <machine>.471machine # [ 1.678426] systemd[1]: bpf-restrict-fs: LSM BPF program attached472machine # [ 1.712118] systemd[1]: Queued start job for default target Initrd Default Target.473machine # [ 1.721591] systemd[1]: Created slice Slice /system/modprobe.474machine # [ 1.722859] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.475machine # [ 1.724349] systemd[1]: Expecting device /dev/disk/by-label/nixos...476machine # [ 1.725485] systemd[1]: Reached target Path Units.477machine # [ 1.726382] systemd[1]: Reached target Slice Units.478machine # [ 1.727290] systemd[1]: Reached target Swaps.479machine # [ 1.728097] systemd[1]: Reached target Timer Units.480machine # [ 1.729063] systemd[1]: Listening on D-Bus System Message Bus Socket.481machine # [ 1.730263] systemd[1]: Listening on Journal Socket (/dev/log).482machine # [ 1.731437] systemd[1]: Listening on Journal Sockets.483machine # [ 1.732460] systemd[1]: Listening on udev Control Socket.484machine # [ 1.733513] systemd[1]: Listening on udev Kernel Socket.485machine # [ 1.734521] systemd[1]: Reached target Socket Units.486machine # [ 1.736337] systemd[1]: Starting Create List of Static Device Nodes...487machine # [ 1.739057] systemd[1]: Starting Load Kernel Module 9pnet_virtio...488machine # [ 1.742727] systemd[1]: Starting Load Kernel Module configfs...489machine # [ 1.751051] systemd[1]: Starting Journal Service...490machine # [ 1.755158] systemd[1]: Starting Load Kernel Modules...491machine # [ 1.756159] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os492machine # [ 1.770049] systemd[1]: Starting Coldplug All udev Devices...493machine # [ 1.774256] systemd[1]: Finished Create List of Static Device Nodes.494machine # [ 1.775932] systemd[1]: modprobe@configfs.service: Deactivated successfully.495machine # [ 1.783036] systemd[1]: Finished Load Kernel Module configfs.496machine # [ 1.784443] systemd[1]: Kernel Configuration File System skipped, unmet condition check ConditionPathExists=/sys/kernel/config497machine # [ 1.789032] netfs: FS-Cache loaded498machine # [ 1.795418] 9pnet: Installing 9P2000 support499machine # [ 1.798149] systemd-journald[76]: Collecting audit messages is disabled.500machine # [ 1.800051] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...501machine # [ 1.806716] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.502machine # [ 1.815528] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev503machine # [ 1.821674] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.504machine # [ 1.825491] systemd[1]: Finished Load Kernel Module 9pnet_virtio.505machine # [ 1.827557] systemd[1]: Finished Load Kernel Modules.506machine # [ 1.832165] systemd[1]: Starting Apply Kernel Variables...507machine # [ 1.691878] systemd-modules-load[77]: Using 2[ 1.844060] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.508machine # probe threads509machine # [ 1.694026] systemd-modules-load[77]: Inserted module 'virtio_balloon'510machine # [ 1.695158] systemd-modules-load[77]: Inserted module 'virtio_gpu'511machine # [ 1.696214] systemd-modules-load[77]: Inserted module 'dm_mod'512machine # [ 1.849332] systemd[1]: Started Journal Service.513machine # [ 1.702186] systemd[1]: Finished Apply Kernel Variables.514machine # [ 1.708176] systemd[1]: Starting Create Static Device Nodes in /dev...515machine # [ 1.719344] systemd[1]: Finished Create Static Device Nodes in /dev.516machine # [ 1.721068] systemd[1]: Reached target Preparation for Local File Systems.517machine # [ 1.721991] systemd[1]: Reached target Local File Systems.518machine # [ 1.725901] systemd[1]: Starting Create System Files and Directories...519machine # [ 1.727037] systemd[1]: Starting Rule-based Manager for Device Events and Files...520machine # [ 1.746148] systemd[1]: Finished Create System Files and Directories.521machine # [ 1.753367] systemd-udevd[94]: Using default interface naming scheme 'v261'.522machine # [ 1.769302] systemd[1]: Started Rule-based Manager for Device Events and Files.523machine # [ 1.775585] systemd[1]: Finished Coldplug All udev Devices.524machine # [ 1.776401] systemd[1]: Reached target System Initialization.525machine # [ 1.777165] systemd[1]: Reached target Basic System.526machine # [ 2.051808] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12527machine # [ 2.059683] serio: i8042 KBD port at 0x60,0x64 irq 1528machine # [ 2.060430] serio: i8042 AUX port at 0x60,0x64 irq 12529machine # [ 2.076741] uhci_hcd 0000:00:1d.0: UHCI Host Controller530machine # [ 2.080895] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 1531machine # [ 2.088880] virtio_blk virtio5: 2/0/0 default/read/poll queues532machine # [ 2.089012] uhci_hcd 0000:00:1d.0: detected 2 ports533machine # [ 2.096502] uhci_hcd 0000:00:1d.0: irq 16, io port 0x0000c200534machine # [ 2.099565] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.18535machine # [ 2.100840] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1536machine # [ 2.102179] usb usb1: Product: UHCI Host Controller537machine # [ 2.102854] usb usb1: Manufacturer: Linux 6.18.49 uhci_hcd538machine # [ 2.104788] usb usb1: SerialNumber: 0000:00:1d.0539machine # [ 2.107835] SCSI subsystem initialized540machine # [ 2.108934] hub 1-0:1.0: USB hub found541machine # [ 2.110374] hub 1-0:1.0: 2 ports detected542machine # [ 2.111482] virtio_blk virtio5: [vda] 16777216 512-byte logical blocks (8.59 GB/8.00 GiB)543machine # [ 2.115099] ehci-pci 0000:00:1d.7: EHCI Host Controller544machine # [ 2.115889] ehci-pci 0000:00:1d.7: new USB bus registered, assigned bus number 2545machine # [ 2.119335] ehci-pci 0000:00:1d.7: irq 19, io mem 0xfebdb000546machine # [ 2.126152] ehci-pci 0000:00:1d.7: USB 2.0 started, EHCI 1.00547machine # [ 2.127863] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.18548machine # [ 2.129951] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1549machine # [ 2.130991] usb usb2: Product: EHCI Host Controller550machine # [ 2.131673] usb usb2: Manufacturer: Linux 6.18.49 ehci_hcd551machine # [ 2.133748] usb usb2: SerialNumber: 0000:00:1d.7552machine # [ 1.982349] (udev-worker)[101]: Network interface NamePolicy= disabled on kernel command line.[ 2.135714] hub 2-0:1.0: USB hub found553machine # 554machine # [ 2.136656] hub 2-0:1.0: 6 ports detected555machine # [ 1.990159] systemd[1]: Starting Virtual Console Setup...556machine # [ 2.160195] hub 1-0:1.0: USB hub found557machine # [ 2.160923] hub 1-0:1.0: 2 ports detected558machine # [ 2.164629] uhci_hcd 0000:00:1d.1: UHCI Host Controller559machine # [ 2.167036] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0560machine # [ 2.170553] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3561machine # [ 2.171635] uhci_hcd 0000:00:1d.1: detected 2 ports562machine # [ 2.019834] systemd-vconsole-setup[121]: Configuration of first virtual console was skipped, ignoring remaining ones.563machine # [ 2.022161] (udev-worker)[114]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.564machine # [ 2.024513] (udev-worker)[114]: Network interface NamePolicy= disabled on kernel command line.565machine # [ 2.027167] systemd[1]: Finished Virtual Console Setup.566machine # [ 2.184267] uhci_hcd 0000:00:1d.1: irq 17, io port 0x0000c220567machine # [ 2.189651] usb usb3: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.18568machine # [ 2.190822] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1569machine # [ 2.041406] systemd[1]: Found device /dev/disk/by-label/nixos.570machine # [ 2.042631] systemd[1]: Reached target Initrd Root Device.571machine # [ 2.195355] usb usb3: Product: UHCI Host Controller572machine # [ 2.196039] usb usb3: Manufacturer: Linux 6.18.49 uhci_hcd573machine # [ 2.196760] usb usb3: SerialNumber: 0000:00:1d.1574machine # [ 2.043649] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos...575machine # [ 2.200170] hub 3-0:1.0: USB hub found576machine # [ 2.200769] hub 3-0:1.0: 2 ports detected577machine # [ 2.205600] uhci_hcd 0000:00:1d.2: UHCI Host Controller578machine # [ 2.206338] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4579machine # [ 2.209124] uhci_hcd 0000:00:1d.2: detected 2 ports580machine # [ 2.209909] uhci_hcd 0000:00:1d.2: irq 18, io port 0x0000c240581machine # [ 2.211311] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.18582machine # [ 2.212619] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1583machine # [ 2.213916] usb usb4: Product: UHCI Host Controller584machine # [ 2.214805] usb usb4: Manufacturer: Linux 6.18.49 uhci_hcd585machine # [ 2.215656] usb usb4: SerialNumber: 0000:00:1d.2586machine # [ 2.216883] hub 4-0:1.0: USB hub found587machine # [ 2.216911] hub 4-0:1.0: 2 ports detected588machine # [ 2.078326] systemd-fsck[129]: nixos: clean, 12/524288 files, 58513/2097152 blocks589machine # [ 2.234034] ahci 0000:00:1f.2: AHCI vers 0001.0000, 32 command slots, 1.5 Gbps, SATA mode590machine # [ 2.084228] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos.591machine # [ 2.238795] ahci 0000:00:1f.2: 6/6 ports implemented (port mask 0x3f)592machine # [ 2.240422] ahci 0000:00:1f.2: flags: 64bit ncq only593machine # [ 2.244290] scsi host0: ahci594machine # [ 2.245470] scsi host1: ahci595machine # [ 2.246580] scsi host2: ahci596machine # [ 2.247400] scsi host3: ahci597machine # [ 2.248716] scsi host4: ahci598machine # [ 2.249649] scsi host5: ahci599machine # [ 2.250643] ata1: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc100 irq 45 lpm-pol 1600machine # [ 2.252199] ata2: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc180 irq 45 lpm-pol 1601machine # [ 2.253495] ata3: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc200 irq 45 lpm-pol 1602machine # [ 2.254635] ata4: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc280 irq 45 lpm-pol 1603machine # [ 2.255782] ata5: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc300 irq 45 lpm-pol 1604machine # [ 2.257363] ata6: SATA max UDMA/133 abar m4096@0xfebdc000 port 0xfebdc380 irq 45 lpm-pol 1605machine # [ 2.380144] usb 2-1: new high-speed USB device number 2 using ehci-pci606machine # [ 2.511410] usb 2-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00607machine # [ 2.514321] usb 2-1: New USB device strings: Mfr=1, Product=3, SerialNumber=10608machine # [ 2.516953] usb 2-1: Product: QEMU USB Tablet609machine # [ 2.518589] usb 2-1: Manufacturer: QEMU610machine # [ 2.520039] usb 2-1: SerialNumber: 28754-0000:00:1d.7-1611machine # [ 2.552234] hid: raw HID events driver (C) Jiri Kosina612machine # [ 2.569208] ata6: SATA link down (SStatus 0 SControl 300)613machine # [ 2.571478] ata2: SATA link down (SStatus 0 SControl 300)614machine # [ 2.573706] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)615machine # [ 2.576399] ata1: SATA link down (SStatus 0 SControl 300)616machine # [ 2.578383] ata3.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100617machine # [ 2.580635] ata3.00: applying bridge limits618machine # [ 2.582596] ata5: SATA link down (SStatus 0 SControl 300)619machine # [ 2.584594] ata3.00: configured for UDMA/100620machine # [ 2.586516] ata4: SATA link down (SStatus 0 SControl 300)621machine # [ 2.589394] scsi 2:0:0:0: CD-ROM QEMU QEMU DVD-ROM 2.5+ PQ: 0 ANSI: 5622machine # [ 2.637306] usbcore: registered new interface driver usbhid623machine # [ 2.638851] usbhid: USB HID core driver624machine # [ 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/input2625machine # [ 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/input0626machine # [ 2.677244] sr 2:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray627machine # [ 2.701423] cdrom: Uniform CD-ROM driver Revision: 3.20628machine # [ 2.622328] systemd[1]: Mounting /sysroot...629machine # [ 2.880799] EXT4-fs (vda): mounted filesystem 7dcebace-693b-40e4-9567-e02b02c81a92 r/w with ordered data mode. Quota mode: none.630machine # [ 2.734853] systemd[1]: Mounted /sysroot.631machine # [ 2.736147] systemd[1]: Reached target Initrd Root File System.632machine # [ 2.741338] systemd[1]: Mounting /sysroot/nix/.ro-store...633machine # [ 2.752510] systemd[1]: Mounting /sysroot/nix/.rw-store...634machine # [ 2.755826] systemd[1]: Mounting /sysroot/run...635machine # [ 2.761230] systemd[1]: Mounting /sysroot/tmp/shared...636machine # [ 2.764613] systemd[1]: Mounting /sysroot/tmp/xchg...637machine # [ 2.931015] 9p: Installing v9fs 9p2000 file system support638machine # [ 2.779914] systemd[1]: Starting Mountpoints Configured in the Real Root...639machine # [ 2.785317] systemd[1]: Mounted /sysroot/nix/.rw-store.640machine # [ 2.786841] systemd[1]: Mounted /sysroot/tmp/xchg.641machine # [ 2.788275] systemd[1]: Mounted /sysroot/nix/.ro-store.642machine # [ 2.791150] systemd[1]: Mounted /sysroot/tmp/shared.643machine # [ 2.796510] systemd-sysroot-fstab-check[171]: /sysroot should be mounted in the initrd, will request daemon-reload.644machine # [ 2.798615] systemd[1]: Mounted /sysroot/run.645machine # [ 2.802206] systemd[1]: Starting rw-sysroot-nix-store.service...646machine # [ 2.803377] systemd[1]: Reload requested from client PID 171 ('systemd-sysroot') (unit initrd-parse-etc.service)...647machine # [ 2.804808] systemd[1]: Reloading...648machine # [ 2.863159] systemd[1]: Reloading finished in 58 ms.649machine # [ 2.880938] systemd-sysroot-fstab-check[171]: Requesting initrd-fs.target/start/replace...650machine # [ 2.883457] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.651machine # [ 2.885412] systemd[1]: Finished rw-sysroot-nix-store.service.652machine # [ 2.886970] systemd-sysroot-fstab-check[171]: Requesting swap.target/start/replace...653machine # [ 2.889118] systemd[1]: initrd-parse-etc.service: Deactivated successfully.654machine # [ 2.890942] systemd[1]: Finished Mountpoints Configured in the Real Root.655machine # [ 2.892874] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies.656machine # [ 2.894856] systemd[1]: Starting rw-sysroot-nix-store.service...657machine # [ 2.906584] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.658machine # [ 2.908274] systemd[1]: Finished rw-sysroot-nix-store.service.659machine # [ 3.623369] systemd[1]: Mounting /sysroot/nix/store...660machine # [ 3.678939] systemd[1]: Mounted /sysroot/nix/store.661machine # [ 3.680685] systemd[1]: Reached target Initrd File Systems.662machine # [ 3.684183] systemd[1]: Starting Find NixOS closure...663machine # [ 3.686300] systemd[1]: Starting Create Volatile Files and Directories in the Real Root...664machine # [ 3.717509] systemd[1]: Finished Create Volatile Files and Directories in the Real Root.665machine # [ 3.720241] systemd[1]: sysroot-run-credentials-systemd\x2dtmpfiles\x2dsetup\x2dsysroot.service.mount: Deactivated successfully.666machine # [ 3.739055] systemd[1]: Finished Find NixOS closure.667machine # [ 3.740552] systemd[1]: Reached target Initrd Default Target.668machine # [ 3.742201] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...669machine # [ 3.765151] systemd[1]: Stopped target Initrd Default Target.670machine # [ 3.767259] systemd[1]: Stopped target Basic System.671machine # [ 3.768742] systemd[1]: Stopped target Initrd Root Device.672machine # [ 3.770202] systemd[1]: Stopped target Path Units.673machine # [ 3.771456] systemd[1]: systemd-ask-password-console.path: Deactivated successfully.674machine # [ 3.773877] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.675machine # [ 3.776082] systemd[1]: Stopped target Slice Units.676machine # [ 3.777525] systemd[1]: Stopped target Socket Units.677machine # [ 3.779151] systemd[1]: Stopped target System Initialization.678machine # [ 3.780976] systemd[1]: Stopped target Swaps.679machine # [ 3.782105] systemd[1]: Stopped target Timer Units.680machine # [ 3.783374] systemd[1]: dbus.socket: Deactivated successfully.681machine # [ 3.784724] systemd[1]: Closed D-Bus System Message Bus Socket.682machine # [ 3.786144] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully.683machine # [ 3.787639] systemd[1]: Stopped Find NixOS closure.684machine # [ 3.790455] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio685machine # [ 3.792382] systemd[1]: Starting rw-sysroot-nix-store.service...686machine # [ 3.793839] systemd[1]: systemd-sysctl.service: Deactivated successfully.687machine # [ 3.794792] systemd[1]: Stopped Apply Kernel Variables.688machine # [ 3.795583] systemd[1]: systemd-modules-load.service: Deactivated successfully.689machine # [ 3.796589] systemd[1]: Stopped Load Kernel Modules.690machine # [ 3.797351] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully.691machine # [ 3.798382] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root.692machine # [ 3.799428] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.693machine # [ 3.802553] systemd[1]: Stopped Create System Files and Directories.694machine # [ 3.803739] systemd[1]: Stopped target Local File Systems.695machine # [ 3.804574] systemd[1]: Stopped target Preparation for Local File Systems.696machine # [ 3.805603] systemd[1]: systemd-udev-trigger.service: Deactivated successfully.697machine # [ 3.806664] systemd[1]: Stopped Coldplug All udev Devices.698machine # [ 3.807487] systemd[1]: Stopping Rule-based Manager for Device Events and Files...699machine # [ 3.808530] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.700machine # [ 3.809551] systemd[1]: Stopped Virtual Console Setup.701machine # [ 3.810333] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.702machine # [ 3.811231] systemd[1]: Finished rw-sysroot-nix-store.service.703machine # [ 3.812022] systemd[1]: initrd-cleanup.service: Deactivated successfully.704machine # [ 3.812895] systemd[1]: Finished Cleaning Up and Shutting Down Daemons.705machine # [ 3.815836] systemd[1]: systemd-udevd.service: Deactivated successfully.706machine # [ 3.816834] systemd[1]: Stopped Rule-based Manager for Device Events and Files.707machine # [ 3.817771] systemd[1]: systemd-udevd-control.socket: Deactivated successfully.708machine # [ 3.818725] systemd[1]: Closed udev Control Socket.709machine # [ 3.819440] systemd[1]: Starting Cleanup udev Database...710machine # [ 3.820229] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.711machine # [ 3.821249] systemd[1]: Stopped Create Static Device Nodes in /dev.712machine # [ 3.822083] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully.713machine # [ 3.823100] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully.714machine # [ 3.823983] systemd[1]: kmod-static-nodes.service: Deactivated successfully.715machine # [ 3.824881] systemd[1]: Stopped Create List of Static Device Nodes.716machine # [ 3.836615] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.717machine # [ 3.837799] systemd[1]: Finished Cleanup udev Database.718machine # [ 3.838590] systemd[1]: Reached target Switch Root.719machine # [ 3.839347] systemd[1]: Starting NixOS Activation...720machine # [ 4.005248] initrd-nixos-activation-start[218]: booting system configuration /nix/store/2j5h69yyypr6ipr8f13644brlzqaxd9q-nixos-system-machine-test721machine # [ 4.070744] initrd-nixos-activation-start[218]: running activation script...722machine # [ 4.511603] initrd-nixos-activation-start[241]: setting up /etc...723machine # [ 4.779022] systemd[1]: initrd-nixos-activation.service: Deactivated successfully.724machine # [ 4.780081] systemd[1]: Finished NixOS Activation.725machine # [ 4.782088] systemd[1]: Starting Switch Root...726machine # [ 4.800990] systemd[1]: Switching root.727machine # [ 4.989950] systemd-journald[76]: Received SIGTERM from PID 1 (systemd).728machine # [ 5.132339] NET: Registered PF_VSOCK protocol family729machine # [ 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)730machine # [ 5.546743] systemd[1]: Detected virtualization kvm.731machine # [ 5.548553] systemd[1]: Detected architecture x86-64.732machine # [ 5.550487] systemd[1]: Detected first boot.733machine # [ 5.556772] systemd[1]: Initializing machine ID from random generator.734machine # [ 5.705674] systemd[1]: bpf-restrict-fs: LSM BPF program attached735machine # [ 5.827407] systemd[1]: Applying preset policy.736machine # [ 6.324759] systemd[1]: Populated /etc with preset unit settings.737machine # [ 6.867320] systemd[1]: initrd-switch-root.service: Deactivated successfully.738machine # [ 6.868698] systemd[1]: Stopped initrd-switch-root.service.739machine # [ 6.871397] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.740machine # [ 6.873625] systemd[1]: Created slice Slice /system/getty.741machine # [ 6.875011] systemd[1]: Created slice User and Session Slice.742machine # [ 6.875863] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.743machine # [ 6.877062] systemd[1]: Started Forward Password Requests to Wall Directory Watch.744machine # [ 6.878153] systemd[1]: Expecting device /dev/hvc0...745machine # [ 6.878853] systemd[1]: Expecting device /dev/ttyS0...746machine # [ 6.879616] systemd[1]: Reached target Local Encrypted Volumes.747machine # [ 6.880458] systemd[1]: Stopped target initrd-fs.target.748machine # [ 6.881199] systemd[1]: Stopped target initrd-root-fs.target.749machine # [ 6.881973] systemd[1]: Stopped target initrd-switch-root.target.750machine # [ 6.882817] systemd[1]: Reached target Virtual Machines and Containers.751machine # [ 6.883802] systemd[1]: Reached target Path Units.752machine # [ 6.884571] systemd[1]: Reached target Remote File Systems.753machine # [ 6.885377] systemd[1]: Reached target Slice Units.754machine # [ 6.886070] systemd[1]: Reached target Swaps.755machine # [ 6.889567] systemd[1]: Listening on Query the User Interactively for a Password.756machine # [ 6.893668] systemd[1]: Listening on Process Core Dump Socket.757machine # [ 6.896858] systemd[1]: Listening on Credential Encryption/Decryption.758machine # [ 6.899877] systemd[1]: Listening on Factory Reset Management.759machine # [ 6.900806] systemd[1]: Listening on Hostname Service Socket.760machine # [ 6.905027] systemd[1]: Starting Journal Log Access Socket...761machine # [ 6.906380] systemd[1]: Listening on Journal Audit Socket.762machine # [ 6.909522] systemd[1]: Listening on Console Output Muting Service Socket.763machine # [ 6.911002] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.764machine # [ 6.912695] systemd[1]: TPM PCR Measurements skipped, unmet condition check ConditionSecurity=measured-os765machine # [ 6.913995] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki766machine # [ 6.924226] systemd[1]: Listening on Disk Repartitioning Service Socket.767machine # [ 6.925226] systemd[1]: Listening on udev Control Socket.768machine # [ 6.926091] systemd[1]: Listening on udev Varlink Socket.769machine # [ 6.930002] systemd[1]: Mounting Huge Pages File System...770machine # [ 6.932759] systemd[1]: Mounting POSIX Message Queue File System...771machine # [ 6.936486] systemd[1]: Mounting Kernel Debug File System...772machine # [ 6.939534] systemd[1]: Mounting Kernel Trace File System...773machine # [ 6.944277] systemd[1]: Starting Create List of Static Device Nodes...774machine # [ 6.948071] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio775machine # [ 6.952810] systemd[1]: Starting Load Kernel Module configfs...776machine # [ 6.954135] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm777machine # [ 6.956658] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore778machine # [ 6.959593] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse779machine # [ 6.963091] systemd[1]: Mounting FUSE Control File System...780machine # [ 6.965224] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67781machine # [ 6.972591] systemd[1]: Starting Journal Service...782machine # [ 7.003880] systemd[1]: Starting Load Kernel Modules...783machine # [ 7.008491] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...784machine # [ 7.014808] systemd[1]: Starting Remount Root and Kernel File Systems...785machine # [ 7.017299] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os786machine # [ 7.023473] systemd[1]: Starting Coldplug All udev Devices...787machine # [ 7.028416] systemd[1]: Listening on Journal Log Access Socket.788machine # [ 7.041713] systemd[1]: Mounted Huge Pages File System.789machine # [ 7.044427] systemd[1]: Mounted POSIX Message Queue File System.790machine # [ 7.047872] systemd[1]: Mounted Kernel Debug File System.791machine # [ 7.051612] systemd[1]: Mounted Kernel Trace File System.792machine # [ 7.053224] systemd[1]: Mounted FUSE Control File System.793machine # [ 7.056328] systemd[1]: Finished Create List of Static Device Nodes.794machine # [ 7.061156] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...795machine # [ 7.076579] systemd[1]: modprobe@configfs.service: Deactivated successfully.796machine # [ 7.079987] systemd[1]: Finished Load Kernel Module configfs.797machine # [ 7.097032] systemd-journald[311]: Collecting audit messages is enabled.798machine # [ 7.110040] EXT4-fs (vda): re-mounted 7dcebace-693b-40e4-9567-e02b02c81a92.799machine # [ 7.114566] systemd[1]: Finished Remount Root and Kernel File Systems.800machine # [ 7.116343] systemd[1]: Listening on Disk Image Download Service Socket.801machine # [ 7.119057] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore802machine # [ 7.124039] systemd[1]: Starting Load/Save OS Random Seed...803machine # [ 7.124840] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os804machine # [ 7.136134] loop: module loaded805machine # [ 7.142883] systemd[1]: Finished Load Kernel Modules.806machine # [ 6.992580] systemd[1]: Queued start job for default target Multi-User System.807machine # [ 7.146060] systemd[1]: Started Journal Service.808machine # [ 6.994631] systemd[1]: systemd-journald.service: Deactivated successfully.809machine # [ 6.998893] systemd-modules-load[312]: Using 2 probe threads810machine # [ 7.001948] systemd-modules-load[312]: Inserted module 'loop'811machine # [ 7.015488] systemd-oomd[313]: No swap; memory pressure usage will be degraded812machine # [ 7.020168] systemd[1]: Starting Flush Journal to Persistent Storage...813machine # [ 7.023927] systemd[1]: Starting Apply Kernel Variables...814machine # [ 7.026334] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.815machine # [ 7.028327] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.816machine # [ 7.031257] systemd[1]: Starting Create Static Device Nodes in /dev...817machine # [ 7.035487] systemd[1]: Finished Load/Save OS Random Seed.818machine # [ 7.036803] systemd[1]: Reached target First Boot Complete.819machine # [ 7.206324] systemd-journald[311]: Received client request to flush runtime journal.820machine # [ 7.106843] systemd[1]: Finished Apply Kernel Variables.821machine # [ 7.108671] systemd[1]: Finished Create Static Device Nodes in /dev.822machine # [ 7.109640] systemd[1]: Reached target Preparation for Local File Systems.823machine # [ 7.110568] systemd[1]: Starting Rule-based Manager for Device Events and Files...824machine # [ 7.111589] systemd[1]: Finished Flush Journal to Persistent Storage.825machine # [ 7.135934] systemd[1]: Finished Coldplug All udev Devices.826machine # [ 7.184692] systemd-udevd[339]: Using default interface naming scheme 'v261'.827machine # [ 7.279759] systemd[1]: Started Rule-based Manager for Device Events and Files.828machine # [ 7.334847] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs829machine # [ 7.353705] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs830machine # [ 7.366168] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse831machine # [ 7.391519] systemd[1]: Condition check resulted in /dev/hvc0 being skipped.832machine # [ 7.415654] systemd[1]: Condition check resulted in /dev/ttyS0 being skipped.833machine # [ 7.423632] (udev-worker)[348]: Network interface NamePolicy= disabled on kernel command line.834machine # [ 7.428364] (udev-worker)[346]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.835machine # [ 7.430793] (udev-worker)[346]: Network interface NamePolicy= disabled on kernel command line.836machine # [ 7.474052] systemd[1]: Condition check resulted in Virtio network device being skipped.837machine # [ 7.475795] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs838machine # [ 7.477968] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore839machine # [ 7.480140] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67840machine # [ 7.482603] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore841machine # [ 7.484145] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os842machine # [ 7.485854] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-os843machine # [ 7.656408] input: QEMU Virtio Keyboard as /devices/pci0000:00/0000:00:09.0/virtio7/input/input3844machine # [ 7.659392] bochs-drm 0000:00:01.0: vgaarb: deactivate vga console845machine # [ 7.676364] Console: switching to colour dummy device 80x25846machine # [ 7.677429] [drm] Found bochs VGA, ID 0xb0c5.847machine # [ 7.677431] [drm] Framebuffer size 16384 kB @ 0xfd000000, mmio @ 0xfebd0000.848machine # [ 7.679149] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input4849machine # [ 7.679177] bochs-drm 0000:00:01.0: [drm] Registered 1 planes with drm panic850machine # [ 7.680699] [drm] Initialized bochs-drm 1.0.0 for 0000:00:01.0 on minor 0851machine # [ 7.691501] lpc_ich 0000:00:1f.0: I/O space for GPIO uninitialized852machine # [ 7.692031] ACPI: button: Power Button [PWRF]853machine # [ 7.692116] mousedev: PS/2 mouse device common for all mice854machine # [ 7.702693] Console: switching to colour frame buffer device 160x50855machine # [ 7.706754] bochs-drm 0000:00:01.0: [drm] fb0: bochs-drmdrmfb frame buffer device856machine # [ 7.730232] rtc_cmos 00:04: RTC can wake from S4857machine # [ 7.733212] rtc_cmos 00:04: registered as rtc0858machine # [ 7.733819] rtc_cmos 00:04: setting system clock to 2026-09-13T15:16:19 UTC (1789312579)859machine # [ 7.741475] rtc_cmos 00:04: alarms up to one day, y3k, 242 bytes nvram, hpet irqs860machine # [ 7.758359] parport_pc 00:02: reported by Plug and Play ACPI861machine # [ 7.760649] parport0: PC-style at 0x378, irq 7 [PCSPP(,...)]862machine # [ 7.777150] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input6863machine # [ 7.779597] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input5864machine # [ 7.783789] i801_smbus 0000:00:1f.3: SMBus using PCI interrupt865machine # [ 7.784608] i2c i2c-0: Memory type 0x07 not supported yet, not instantiating SPD866machine # [ 7.848617] iTCO_wdt iTCO_wdt.0.auto: Found a ICH9 TCO device (Version=2, TCOBASE=0x0660)867machine # [ 7.700277] systemd[1]: Starting Virtual Console Setup...868machine # [ 7.710463] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.869machine # [ 7.711545] systemd[1]: Stopped Virtual Console Setup.870machine # [ 7.715949] systemd[1]: Starting Virtual Console Setup...871machine # [ 7.719544] systemd[1]: Mounting /run/wrappers...872machine # [ 7.721695] systemd[1]: Mounting Kernel Configuration File System...873machine # [ 7.880005] ppdev: user-space parallel port driver874machine # [ 7.880790] iTCO_wdt iTCO_wdt.0.auto: initialized. heartbeat=30 sec (nowayout=0)875machine # [ 7.753760] systemd[1]: Mounted Kernel Configuration File System.876machine # [ 7.757551] systemd[1]: Mounted /run/wrappers.877machine # [ 7.759619] systemd[1]: Reached target Local File Systems.878machine # [ 7.764604] systemd[1]: Listening on Boot Loader Control Service Socket.879machine # [ 7.766366] systemd[1]: Starting register-nix-paths.service...880machine # [ 7.770124] systemd[1]: Starting Create SUID/SGID Wrappers...881machine # [ 7.773220] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.882machine # [ 7.778169] systemd[1]: Starting Save Transient machine-id to Disk...883machine # [ 7.781104] systemd[1]: Starting Create System Files and Directories...884machine # [ 7.790703] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.885machine # [ 7.792634] systemd[1]: Stopped Virtual Console Setup.886machine # [ 7.799683] systemd[1]: Starting Virtual Console Setup...887machine # [ 7.847531] systemd[1]: Finished Save Transient machine-id to Disk.888machine # [ 8.015575] kvm_amd: TSC scaling supported889machine # [ 8.016319] kvm_amd: Nested Virtualization enabled890machine # [ 8.016855] kvm_amd: Nested Paging enabled891machine # [ 8.017650] kvm_amd: LBR virtualization supported892machine # [ 8.018523] kvm_amd: Virtual VMLOAD VMSAVE supported893machine # [ 8.019231] kvm_amd: Virtual GIF supported894machine # [ 8.019743] kvm_amd: Virtual NMI enabled895machine # [ 7.904199] systemd[1]: Finished Create System Files and Directories.896machine # [ 8.057370] EDAC MC: Ver: 3.0.0897machine # [ 7.908091] systemd[1]: Starting Rebuild Journal Catalog...898machine # [ 7.910241] systemd[1]: Starting Record System Boot/Shutdown in UTMP...899machine # [ 7.946553] systemd[1]: Finished Record System Boot/Shutdown in UTMP.900machine # [ 7.979633] systemd[1]: Finished Rebuild Journal Catalog.901machine # [ 7.982471] systemd[1]: Starting Update is Completed...902machine # [ 8.010262] systemd[1]: Finished Update is Completed.903machine # [ 8.176186] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.904machine # [ 8.177673] systemd[1]: Finished Create SUID/SGID Wrappers.905machine # [ 8.249954] systemd-vconsole-setup[389]: Configuration of first virtual console was skipped, ignoring remaining ones.906machine # [ 8.253219] systemd[1]: Finished Virtual Console Setup.907machine # [ 8.348381] systemd[1]: Finished register-nix-paths.service.908machine # [ 8.349344] systemd[1]: Reached target System Initialization.909machine # [ 8.350459] systemd[1]: Started Discard unused filesystem blocks once a week.910machine # [ 8.351441] systemd[1]: Started Daily Cleanup of Temporary Directories.911machine # [ 8.352372] systemd[1]: Reached target Timer Units.912machine # [ 8.353120] systemd[1]: Listening on D-Bus System Message Bus Socket.913machine # [ 8.354024] systemd[1]: Listening on Nix Daemon Socket.914machine # [ 8.354865] systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.915machine # [ 8.355957] systemd[1]: Reached target Socket Units.916machine # [ 8.356680] systemd[1]: Reached target Basic System.917machine # [ 8.359584] systemd[1]: Started backdoor.service.918machine # [ 8.363812] systemd[1]: Starting Import lastlog data into lastlog2 database...919machine # [ 8.366135] systemd[1]: Starting Name Service Cache Daemon (nsncd)...920machine # [ 8.372491] systemd[1]: Starting Post-Boot Actions...921machine # [ 8.375439] systemd[1]: Started Reset console on configuration changes.922machine # [ 8.378872] systemd[1]: Starting resolvconf update...923machine # [ 8.381985] systemd[1]: Started rustfs.service.924machine # [ 8.385624] systemd[1]: Starting rustfs-setup.service...925machine # [ 8.392383] systemd[1]: Starting D-Bus System Message Bus...926machine # [ 8.427304] systemd[1]: Finished Post-Boot Actions.927machine # [ 8.457395] systemd[1]: Started Name Service Cache Daemon (nsncd).928machine # [ 8.461192] systemd[1]: Reached target Host and Network Name Lookups.929machine # connecting to host...930machine # [ 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"931machine # [ 8.466235] systemd[1]: Reached target User and Group Name Lookups.932machine # [ 8.467752] systemd[1]: Starting User Login Management...933machine # [ 8.470374] systemd[1]: Finished Import lastlog data into lastlog2 database.934machine: Guest shell says: b'Spawning backdoor root shell...\n'935machine: connected to guest root shell936machine: (connecting took 9.13 seconds)937machine: (finished: waiting for the VM to finish booting, in 9.38 seconds)938machine # [ 8.524765] dbus-broker-launch[471]: Looking up NSS user entry for 'systemd-timesync'...939machine # [ 8.530493] systemd-logind[484]: New seat seat0.940machine # [ 8.538070] systemd-logind[484]: Watching system buttons on /dev/input/event3 (Power Button)941machine # [ 8.540068] systemd-logind[484]: Watching system buttons on /dev/input/event2 (QEMU Virtio Keyboard)942machine # [ 8.547455] systemd-logind[484]: Watching system buttons on /dev/input/event0 (AT Translated Set 2 keyboard)943machine # [ 8.550530] systemd[1]: Started User Login Management.944machine # [ 8.557597] systemd[1]: Starting linger-users.service...945machine # [ 8.557950] dbus-broker-launch[471]: NSS returned no entry for 'systemd-timesync'946machine # [ 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"947machine # [ 8.603338] systemd[1]: Started D-Bus System Message Bus.948machine # [ 8.604185] systemd[1]: linger-users.service: Deactivated successfully.949machine # [ 8.605063] systemd[1]: Finished linger-users.service.950machine # [ 8.610169] systemd[1]: Stopped target Host and Network Name Lookups.951machine # [ 8.611797] systemd[1]: Stopping Host and Network Name Lookups...952machine # [ 8.613282] systemd[1]: Stopped target User and Group Name Lookups.953machine # [ 8.614478] systemd[1]: Stopping User and Group Name Lookups...954machine # [ 8.616427] dbus-broker-launch[471]: Ready955machine # [ 8.620369] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...956machine # [ 8.624621] systemd[1]: nscd.service: Deactivated successfully.957machine # [ 8.626320] systemd[1]: Stopped Name Service Cache Daemon (nsncd).958machine # [ 8.633708] systemd[1]: Starting Name Service Cache Daemon (nsncd)...959machine # [ 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"960machine # [ 8.681936] systemd[1]: Started Name Service Cache Daemon (nsncd).961machine # [ 8.683299] systemd[1]: Reached target Host and Network Name Lookups.962machine # [ 8.684333] systemd[1]: Reached target User and Group Name Lookups.963machine # [ 8.694875] systemd[1]: Finished resolvconf update.964machine # [ 8.696648] systemd[1]: Reached target Preparation for Network.965machine # [ 8.701185] systemd[1]: Starting DHCP Client...966machine # [ 8.704745] systemd[1]: Starting Address configuration of eth1...967machine # [ 8.708151] systemd[1]: Starting Extra networking commands....968machine # [ 8.716480] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.969machine # [ 8.794958] network-addresses-eth1-start[587]: adding address 192.168.1.1/24... done970machine # [ 8.805720] network-addresses-eth1-start[587]: adding address 2001:db8:1::1/64... done971machine # [ 8.819813] systemd[1]: Finished Address configuration of eth1.972machine # [ 8.831463] dhcpcd[599]: dhcpcd-10.3.2 starting973machine # [ 8.838847] dhcpcd[647]: dev: loaded udev974machine # [ 9.008678] 8021q: 802.1Q VLAN Support v1.8975machine # [ 9.009828] 8021q: adding VLAN 0 to HW filter on device eth1976machine # [ 8.860858] systemd[1]: Finished Extra networking commands..977machine # [ 8.862885] systemd[1]: Reached target Network.978machine # [ 8.868476] systemd[1]: Starting PostgreSQL Server...979machine # [ 8.869733] systemd[1]: Starting Permit User Sessions...980machine # [ 8.896799] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.981machine # [ 8.908067] systemd[1]: Finished Permit User Sessions.982machine # [ 8.910759] systemd[1]: Started Getty on tty1.983machine # [ 8.912157] systemd[1]: Reached target Login Prompts.984machine # [ 9.122012] cfg80211: Loading compiled-in X.509 certificates for regulatory database985machine # [ 9.145316] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'986machine # [ 9.146596] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'987machine # [ 9.149351] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2988machine # [ 9.152113] cfg80211: failed to load regulatory.db989machine # [ 9.051298] postgresql-pre-start[671]: The files belonging to this database system will be owned by user "postgres".990machine # [ 9.051657] postgresql-pre-start[671]: This user must also own the server process.991machine # [ 9.206685] 8021q: adding VLAN 0 to HW filter on device eth0992machine # [ 9.056521] dhcpcd[647]: eth0: waiting for carrier993machine # [ 9.057472] dhcpcd[647]: eth0: carrier acquired994machine # [ 9.062852] postgresql-pre-start[671]: The database cluster will be initialized with locale "en_US.UTF-8".995machine # [ 9.064451] postgresql-pre-start[671]: The default database encoding has accordingly been set to "UTF8".996machine # [ 9.065920] postgresql-pre-start[671]: The default text search configuration will be set to "english".997machine # [ 9.067452] postgresql-pre-start[671]: Data page checksums are enabled.998machine # [ 9.068606] postgresql-pre-start[671]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok999machine # [ 9.070592] postgresql-pre-start[671]: creating subdirectories ... ok1000machine # [ 9.072073] postgresql-pre-start[671]: selecting dynamic shared memory implementation ... posix1001machine # [ 9.073550] dhcpcd[647]: DUID 00:01:00:01:32:39:7a:c4:52:54:00:12:34:561002machine # [ 9.074728] dhcpcd[647]: eth0: IAID 00:12:34:561003machine # [ 9.075790] dhcpcd[647]: eth0: adding address fe80::5054:ff:fe12:34561004machine # [ 9.147454] postgresql-pre-start[671]: selecting default "max_connections" ... 1001005machine # [ 9.206096] postgresql-pre-start[671]: selecting default "shared_buffers" ... 128MB1006machine # [ 9.237777] dhcpcd[647]: eth0: soliciting a DHCP lease1007machine # [ 9.404133] NET: Registered PF_PACKET protocol family1008machine # [ 9.258464] dhcpcd[647]: eth0: offered 10.0.2.15 from 10.0.2.21009machine # [ 9.266172] dhcpcd[647]: eth0: probing address 10.0.2.15/241010machine # [ 10.700856] dhcpcd[647]: eth0: soliciting an IPv6 router1011machine # [ 10.701759] dhcpcd[647]: eth0: Router Advertisement from fe80::21012machine # [ 10.702595] dhcpcd[647]: eth0: adding address fec0::5054:ff:fe12:3456/641013machine # [ 10.703666] dhcpcd[647]: eth0: adding route to fec0::/641014machine # [ 10.704864] dhcpcd[647]: eth0: adding default route via fe80::21015machine # [ 11.298298] postgresql-pre-start[671]: selecting default time zone ... UTC1016machine # [ 11.302577] postgresql-pre-start[671]: creating configuration files ... ok1017machine # [ 11.554587] postgresql-pre-start[671]: running bootstrap script ... ok1018machine # [ 12.110448] postgresql-pre-start[671]: performing post-bootstrap initialization ... ok1019machine # [ 12.269388] postgresql-pre-start[671]: syncing data to disk ... ok1020machine # [ 12.270399] postgresql-pre-start[671]: initdb: warning: enabling "trust" authentication for local connections1021machine # [ 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.1022machine # [ 12.275115] postgresql-pre-start[671]: Success. You can now start the database server using:1023machine # [ 12.276791] postgresql-pre-start[671]: pg_ctl -D /var/lib/postgresql/18 -l logfile start1024machine # [ 12.415180] postgres[732]: [732] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit1025machine # [ 12.417656] postgres[732]: [732] LOG: listening on IPv4 address "0.0.0.0", port 54321026machine # [ 12.418988] postgres[732]: [732] LOG: listening on IPv6 address "::", port 54321027machine # [ 12.421619] postgres[732]: [732] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"1028machine # [ 12.437455] postgres[741]: [741] LOG: database system was shut down at 2026-09-13 15:16:24 GMT1029machine # [ 12.444401] postgres[732]: [732] LOG: database system is ready to accept connections1030machine # [ 12.450688] systemd[1]: Started PostgreSQL Server.1031machine # [ 12.455120] systemd[1]: Starting PostgreSQL Setup Scripts...1032machine # [ 12.690831] postgresql-setup-start[752]: CREATE DATABASE1033machine # [ 12.739346] postgresql-setup-start[757]: CREATE ROLE1034machine # [ 12.761351] postgresql-setup-start[759]: ALTER DATABASE1035machine # [ 12.765805] systemd[1]: Finished PostgreSQL Setup Scripts.1036machine # [ 12.767097] systemd[1]: Reached target PostgreSQL.1037machine # [ 14.154807] dhcpcd[647]: eth0: leased 10.0.2.15 for 86400 seconds1038machine # [ 14.157902] dhcpcd[647]: eth0: adding route to 10.0.2.0/241039machine # [ 14.160256] dhcpcd[647]: eth0: adding default route via 10.0.2.21040machine # [ 14.352624] systemd[1]: Started DHCP Client.1041machine # [ 14.354793] systemd[1]: Reached target Network is Online.1042machine # [ 14.360190] systemd[1]: Starting k3s service...1043machine # [ 14.532373] k3s[835]: time="2026-09-13T15:16:26Z" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock"1044machine # [ 14.532624] k3s[835]: time="2026-09-13T15:16:26Z" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/76c98da5fd74d9a243cba8d533ae287fc547ab08ccd8c5ea4811608ce7075724"1045machine # [ 18.082663] rustfs-setup-start[852]: mb s3://niks31046machine # [ 18.088563] systemd[1]: Finished rustfs-setup.service.1047machine # [ 18.605343] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Starting k3s 1.35.8+k3s1 (e952d68a)"1048machine # [ 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"1049machine # [ 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"1050machine # [ 18.616506] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Configuring database table schema and indexes, this may take a moment..."1051machine # [ 18.629545] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Database tables and indexes are up to date"1052machine # [ 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..."1053machine # [ 18.634953] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Startup VACUUM completed successfully"1054machine # [ 18.637396] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Kine available at unix://kine.sock"1055machine # [ 18.638578] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"1056machine # [ 18.640729] k3s[835]: time="2026-09-13T15:16:30Z" level=info msg="Datastore connection validated successfully, proceeding with bootstrap data generation"1057machine # [ 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"1058machine # [ 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"1059machine # [ 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"1060machine # [ 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"1061machine # [ 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"1062machine # [ 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"1063machine # [ 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"1064machine # [ 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"1065machine # [ 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"1066machine # [ 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"1067machine # [ 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"1068machine # [ 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"1069machine # [ 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"1070machine # [ 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"1071machine # [ 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"1072machine # [ 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"1073machine # [ 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"1074machine # [ 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"1075machine # [ 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"1076machine # [ 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"1077machine # [ 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]"1078machine # [ 19.509302] k3s[835]: time="2026-09-13T15:16:31Z" level=info msg="Password verified locally for node machine"1079machine # [ 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"1080machine # [ 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"1081machine # [ 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"1082machine # [ 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"1083machine # [ 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"1084machine # [ 20.074277] k3s[835]: time="2026-09-13T15:16:31Z" level=info msg="Module overlay was already loaded"1085machine # [ 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.1086machine # [ 20.333086] Bridge firewalling registered1087machine # [ 20.204215] k3s[835]: time="2026-09-13T15:16:32Z" level=warning msg="Failed to load kernel module iptable_nat with modprobe"1088machine # [ 20.227974] k3s[835]: time="2026-09-13T15:16:32Z" level=warning msg="Failed to load kernel module iptable_filter with modprobe"1089machine # [ 20.249472] k3s[835]: time="2026-09-13T15:16:32Z" level=warning msg="Failed to load kernel module nft-expr-counter with modprobe"1090machine # [ 20.344552] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Set sysctl 'net/ipv4/conf/all/forwarding' to 1"1091machine # [ 20.346698] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_max' to 131072"1092machine # [ 20.348764] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400"1093machine # [ 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"1094machine # [ 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"1095machine # [ 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"1096machine # [ 20.356941] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Handling backend connection request [machine]"1097machine # [ 20.358574] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Creating k3s-cert-monitor event broadcaster"1098machine # [ 20.359863] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Saving cluster bootstrap data to datastore"1099machine # [ 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"1100machine # [ 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"1101machine # [ 20.364745] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Opening etcd client connection with endpoints [unix://kine.sock]"1102machine # [ 20.366912] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Connection to etcd is ready"1103machine # [ 20.368306] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="ETCD server is now running"1104machine # [ 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"1105machine # [ 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"1106machine # [ 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"1107machine # [ 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"1108machine # [ 20.432275] k3s[835]: I0913 15:16:32.289450 835 options.go:263] external host was not specified, using 10.0.2.151109machine # [ 20.433596] k3s[835]: I0913 15:16:32.295599 835 server.go:158] Version: v1.35.8+k3s11110machine # [ 20.434847] k3s[835]: I0913 15:16:32.295769 835 server.go:160] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1111machine # [ 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"1112machine # [ 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}"1113machine # [ 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"1114machine # [ 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}"1115machine # [ 20.444299] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"1116machine # [ 20.446069] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Run: k3s kubectl"1117machine # [ 20.460716] k3s[835]: time="2026-09-13T15:16:32Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log"1118machine # [ 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"1119machine # [ 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"1120machine # [ 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"1121machine # [ 20.604602] k3s[835]: I0913 15:16:32.522680 835 shared_informer.go:349] "Waiting for caches to sync" controller="node_authorizer"1122machine # [ 20.608370] k3s[835]: I0913 15:16:32.526445 835 shared_informer.go:370] "Waiting for caches to sync"1123machine # [ 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.1124machine # [ 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.1125machine # [ 20.623202] k3s[835]: I0913 15:16:32.538188 835 instance.go:240] Using reconciler: lease1126machine # [ 20.627796] k3s[835]: I0913 15:16:32.545789 835 handler.go:304] Adding GroupVersion apiextensions.k8s.io v1 to ResourceManager1127machine # [ 20.629277] k3s[835]: W0913 15:16:32.545820 835 genericapiserver.go:787] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources.1128machine # [ 20.632696] k3s[835]: I0913 15:16:32.550790 835 cidrallocator.go:198] starting ServiceCIDR Allocator Controller1129machine # [ 20.673621] k3s[835]: I0913 15:16:32.591595 835 handler.go:304] Adding GroupVersion v1 to ResourceManager1130machine # [ 20.675305] k3s[835]: I0913 15:16:32.591749 835 apis.go:112] API group "internal.apiserver.k8s.io" is not enabled, skipping.1131machine # [ 20.709948] k3s[835]: I0913 15:16:32.627980 835 apis.go:112] API group "storagemigration.k8s.io" is not enabled, skipping.1132machine # [ 20.763747] k3s[835]: I0913 15:16:32.681509 835 handler.go:304] Adding GroupVersion authentication.k8s.io v1 to ResourceManager1133machine # [ 20.765468] k3s[835]: W0913 15:16:32.683569 835 genericapiserver.go:787] Skipping API authentication.k8s.io/v1beta1 because it has no resources.1134machine # [ 20.769231] k3s[835]: W0913 15:16:32.685671 835 genericapiserver.go:787] Skipping API authentication.k8s.io/v1alpha1 because it has no resources.1135machine # [ 20.771474] k3s[835]: I0913 15:16:32.685995 835 handler.go:304] Adding GroupVersion authorization.k8s.io v1 to ResourceManager1136machine # [ 20.773116] k3s[835]: W0913 15:16:32.686010 835 genericapiserver.go:787] Skipping API authorization.k8s.io/v1beta1 because it has no resources.1137machine # [ 20.775406] k3s[835]: I0913 15:16:32.686568 835 handler.go:304] Adding GroupVersion autoscaling v2 to ResourceManager1138machine # [ 20.777254] k3s[835]: I0913 15:16:32.687006 835 handler.go:304] Adding GroupVersion autoscaling v1 to ResourceManager1139machine # [ 20.779122] k3s[835]: W0913 15:16:32.687020 835 genericapiserver.go:787] Skipping API autoscaling/v2beta1 because it has no resources.1140machine # [ 20.780791] k3s[835]: W0913 15:16:32.687030 835 genericapiserver.go:787] Skipping API autoscaling/v2beta2 because it has no resources.1141machine # [ 20.782994] k3s[835]: I0913 15:16:32.690998 835 handler.go:304] Adding GroupVersion batch v1 to ResourceManager1142machine # [ 20.784834] k3s[835]: W0913 15:16:32.691026 835 genericapiserver.go:787] Skipping API batch/v1beta1 because it has no resources.1143machine # [ 20.786713] k3s[835]: I0913 15:16:32.691695 835 handler.go:304] Adding GroupVersion certificates.k8s.io v1 to ResourceManager1144machine # [ 20.788566] k3s[835]: W0913 15:16:32.691712 835 genericapiserver.go:787] Skipping API certificates.k8s.io/v1beta1 because it has no resources.1145machine # [ 20.790191] k3s[835]: W0913 15:16:32.691724 835 genericapiserver.go:787] Skipping API certificates.k8s.io/v1alpha1 because it has no resources.1146machine # [ 20.791775] k3s[835]: I0913 15:16:32.692062 835 handler.go:304] Adding GroupVersion coordination.k8s.io v1 to ResourceManager1147machine # [ 20.793254] k3s[835]: W0913 15:16:32.692078 835 genericapiserver.go:787] Skipping API coordination.k8s.io/v1beta1 because it has no resources.1148machine # [ 20.795489] k3s[835]: W0913 15:16:32.692088 835 genericapiserver.go:787] Skipping API coordination.k8s.io/v1alpha2 because it has no resources.1149machine # [ 20.797686] k3s[835]: I0913 15:16:32.692517 835 handler.go:304] Adding GroupVersion discovery.k8s.io v1 to ResourceManager1150machine # [ 20.799718] k3s[835]: W0913 15:16:32.692535 835 genericapiserver.go:787] Skipping API discovery.k8s.io/v1beta1 because it has no resources.1151machine # [ 20.801918] k3s[835]: I0913 15:16:32.694085 835 handler.go:304] Adding GroupVersion networking.k8s.io v1 to ResourceManager1152machine # [ 20.803894] k3s[835]: W0913 15:16:32.694102 835 genericapiserver.go:787] Skipping API networking.k8s.io/v1beta1 because it has no resources.1153machine # [ 20.806174] k3s[835]: I0913 15:16:32.694519 835 handler.go:304] Adding GroupVersion node.k8s.io v1 to ResourceManager1154machine # [ 20.807988] k3s[835]: W0913 15:16:32.694535 835 genericapiserver.go:787] Skipping API node.k8s.io/v1beta1 because it has no resources.1155machine # [ 20.809848] k3s[835]: W0913 15:16:32.694546 835 genericapiserver.go:787] Skipping API node.k8s.io/v1alpha1 because it has no resources.1156machine # [ 20.811399] k3s[835]: I0913 15:16:32.695232 835 handler.go:304] Adding GroupVersion policy v1 to ResourceManager1157machine # [ 20.813073] k3s[835]: W0913 15:16:32.695249 835 genericapiserver.go:787] Skipping API policy/v1beta1 because it has no resources.1158machine # [ 20.814806] k3s[835]: I0913 15:16:32.696558 835 handler.go:304] Adding GroupVersion rbac.authorization.k8s.io v1 to ResourceManager1159machine # [ 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.1160machine # [ 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.1161machine # [ 20.820732] k3s[835]: I0913 15:16:32.696908 835 handler.go:304] Adding GroupVersion scheduling.k8s.io v1 to ResourceManager1162machine # [ 20.822146] k3s[835]: W0913 15:16:32.696923 835 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1beta1 because it has no resources.1163machine # [ 20.824396] k3s[835]: W0913 15:16:32.696934 835 genericapiserver.go:787] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources.1164machine # [ 20.826478] k3s[835]: I0913 15:16:32.698383 835 handler.go:304] Adding GroupVersion storage.k8s.io v1 to ResourceManager1165machine # [ 20.828443] k3s[835]: W0913 15:16:32.698536 835 genericapiserver.go:787] Skipping API storage.k8s.io/v1beta1 because it has no resources.1166machine # [ 20.830605] k3s[835]: W0913 15:16:32.698549 835 genericapiserver.go:787] Skipping API storage.k8s.io/v1alpha1 because it has no resources.1167machine # [ 20.832387] k3s[835]: I0913 15:16:32.699332 835 handler.go:304] Adding GroupVersion flowcontrol.apiserver.k8s.io v1 to ResourceManager1168machine # [ 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.1169machine # [ 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.1170machine # [ 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.1171machine # [ 20.840842] k3s[835]: I0913 15:16:32.702123 835 handler.go:304] Adding GroupVersion apps v1 to ResourceManager1172machine # [ 20.842550] k3s[835]: W0913 15:16:32.702232 835 genericapiserver.go:787] Skipping API apps/v1beta2 because it has no resources.1173machine # [ 20.844604] k3s[835]: W0913 15:16:32.702245 835 genericapiserver.go:787] Skipping API apps/v1beta1 because it has no resources.1174machine # [ 20.846072] k3s[835]: I0913 15:16:32.703526 835 handler.go:304] Adding GroupVersion admissionregistration.k8s.io v1 to ResourceManager1175machine # [ 20.847658] k3s[835]: W0913 15:16:32.703545 835 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources.1176machine # [ 20.849727] k3s[835]: W0913 15:16:32.703556 835 genericapiserver.go:787] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources.1177machine # [ 20.852119] k3s[835]: I0913 15:16:32.703939 835 handler.go:304] Adding GroupVersion events.k8s.io v1 to ResourceManager1178machine # [ 20.854178] k3s[835]: W0913 15:16:32.703956 835 genericapiserver.go:787] Skipping API events.k8s.io/v1beta1 because it has no resources.1179machine # [ 20.856366] k3s[835]: I0913 15:16:32.705360 835 handler.go:304] Adding GroupVersion resource.k8s.io v1 to ResourceManager1180machine # [ 20.858332] k3s[835]: W0913 15:16:32.705378 835 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta2 because it has no resources.1181machine # [ 20.860094] k3s[835]: W0913 15:16:32.705389 835 genericapiserver.go:787] Skipping API resource.k8s.io/v1beta1 because it has no resources.1182machine # [ 20.861639] k3s[835]: W0913 15:16:32.705398 835 genericapiserver.go:787] Skipping API resource.k8s.io/v1alpha3 because it has no resources.1183machine # [ 20.863585] k3s[835]: I0913 15:16:32.707669 835 handler.go:304] Adding GroupVersion apiregistration.k8s.io v1 to ResourceManager1184machine # [ 20.865738] k3s[835]: W0913 15:16:32.707688 835 genericapiserver.go:787] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources.1185machine # [ 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"1186machine # [ 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"1187machine # [ 21.195935] k3s[835]: I0913 15:16:33.108984 835 secure_serving.go:211] Serving securely on 127.0.0.1:64441188machine # [ 21.197121] k3s[835]: I0913 15:16:33.109100 835 apf_controller.go:377] Starting API Priority and Fairness config controller1189machine # [ 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"1190machine # [ 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"1191machine # [ 21.203516] k3s[835]: I0913 15:16:33.109677 835 local_available_controller.go:156] Starting LocalAvailability controller1192machine # [ 21.204833] k3s[835]: I0913 15:16:33.109681 835 tlsconfig.go:243] "Starting DynamicServingCertificateController"1193machine # [ 21.206112] k3s[835]: I0913 15:16:33.109692 835 cache.go:32] Waiting for caches to sync for LocalAvailability controller1194machine # [ 21.207463] k3s[835]: I0913 15:16:33.109740 835 controller.go:80] Starting OpenAPI V3 AggregationController1195machine # [ 21.208670] k3s[835]: I0913 15:16:33.109930 835 customresource_discovery_controller.go:294] Starting DiscoveryController1196machine # [ 21.210061] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Starting apiserver lease garbage collector" logger=k3s1197machine # [ 21.211365] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Waiting for caches to sync" logger=k3s1198machine # [ 21.212483] k3s[835]: I0913 15:16:33.110079 835 aggregator.go:185] waiting for initial CRD sync...1199machine # [ 21.213693] k3s[835]: I0913 15:16:33.110101 835 controller.go:78] Starting OpenAPI AggregationController1200machine # [ 21.214959] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Starting legacy_token_tracking_controller" logger=k3s1201machine # [ 21.216204] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Waiting for caches to sync" logger=k3s1202machine # [ 21.217393] k3s[835]: I0913 15:16:33.110634 835 system_namespaces_controller.go:66] Starting system namespaces controller1203machine # [ 21.218712] k3s[835]: I0913 15:16:33.110863 835 controller.go:142] Starting OpenAPI controller1204machine # [ 21.219837] k3s[835]: I0913 15:16:33.110930 835 controller.go:90] Starting OpenAPI V3 controller1205machine # [ 21.220914] k3s[835]: I0913 15:16:33.110962 835 naming_controller.go:305] Starting NamingConditionController1206machine # [ 21.222171] k3s[835]: I0913 15:16:33.111030 835 nonstructuralschema_controller.go:202] Starting NonStructuralSchemaConditionController1207machine # [ 21.223628] k3s[835]: I0913 15:16:33.111064 835 apiapproval_controller.go:196] Starting KubernetesAPIApprovalPolicyConformantConditionController1208machine # [ 21.225184] k3s[835]: I0913 15:16:33.111093 835 crd_finalizer.go:273] Starting CRDFinalizer1209machine # [ 21.226364] k3s[835]: I0913 15:16:33.111190 835 repairip.go:210] Starting ipallocator-repair-controller1210machine # [ 21.227511] k3s[835]: I0913 15:16:33.111203 835 shared_informer.go:349] "Waiting for caches to sync" controller="ipallocator-repair-controller"1211machine # [ 21.229061] k3s[835]: I0913 15:16:33.111500 835 crdregistration_controller.go:114] Starting crd-autoregister controller1212machine # [ 21.230446] k3s[835]: I0913 15:16:33.111514 835 shared_informer.go:349] "Waiting for caches to sync" controller="crd-autoregister"1213machine # [ 21.231841] k3s[835]: I0913 15:16:33.111579 835 default_servicecidr_controller.go:110] Starting kubernetes-service-cidr-controller1214machine # [ 21.233239] k3s[835]: I0913 15:16:33.111595 835 shared_informer.go:349] "Waiting for caches to sync" controller="kubernetes-service-cidr-controller"1215machine # [ 21.234897] k3s[835]: I0913 15:16:33.112935 835 cluster_authentication_trust_controller.go:459] Starting cluster_authentication_trust_controller controller1216machine # [ 21.236551] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Waiting for caches to sync" logger=k3s1217machine # [ 21.237773] k3s[835]: I0913 15:16:33.113034 835 controller.go:113] "Deleting old lease on startup" lease="kube-system/apiserver-ik4pcwfs7qgdl76byc4pomgvia"1218machine # [ 21.239457] k3s[835]: I0913 15:16:33.113243 835 remote_available_controller.go:425] Starting RemoteAvailability controller1219machine # [ 21.240838] k3s[835]: I0913 15:16:33.113255 835 cache.go:32] Waiting for caches to sync for RemoteAvailability controller1220machine # [ 21.242143] k3s[835]: I0913 15:16:33.113298 835 apiservice_controller.go:100] Starting APIServiceRegistrationController1221machine # [ 21.243547] k3s[835]: I0913 15:16:33.113308 835 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller1222machine # [ 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"1223machine # [ 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"1224machine # [ 21.291704] k3s[835]: I0913 15:16:33.209749 835 cache.go:39] Caches are synced for LocalAvailability controller1225machine # [ 21.293112] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Caches are synced" logger=k3s1226machine # [ 21.296053] k3s[835]: I0913 15:16:33.212650 835 shared_informer.go:356] "Caches are synced" controller="kubernetes-service-cidr-controller"1227machine # [ 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]1228machine # [ 21.299156] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Caches are synced" logger=k3s1229machine # [ 21.300191] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="Caches are synced" logger=k3s1230machine # [ 21.301316] k3s[835]: I0913 15:16:33.213309 835 cache.go:39] Caches are synced for RemoteAvailability controller1231machine # [ 21.302545] k3s[835]: I0913 15:16:33.213350 835 cache.go:39] Caches are synced for APIServiceRegistrationController controller1232machine # [ 21.303964] k3s[835]: I0913 15:16:33.213616 835 shared_informer.go:356] "Caches are synced" controller="ipallocator-repair-controller"1233machine # [ 21.305486] k3s[835]: I0913 15:16:33.213654 835 shared_informer.go:356] "Caches are synced" controller="crd-autoregister"1234machine # [ 21.306831] k3s[835]: I0913 15:16:33.216237 835 handler_discovery.go:451] Starting ResourceDiscoveryManager1235machine # [ 21.308064] k3s[835]: I0913 15:16:33.216384 835 aggregator.go:187] initial CRD sync complete...1236machine # [ 21.309173] k3s[835]: I0913 15:16:33.216396 835 autoregister_controller.go:144] Starting autoregister controller1237machine # [ 21.310500] k3s[835]: I0913 15:16:33.216407 835 cache.go:32] Waiting for caches to sync for autoregister controller1238machine # [ 21.311771] k3s[835]: I0913 15:16:33.216418 835 cache.go:39] Caches are synced for autoregister controller1239machine # [ 21.313018] k3s[835]: I0913 15:16:33.224588 835 shared_informer.go:356] "Caches are synced" controller="node_authorizer"1240machine # [ 21.314407] k3s[835]: I0913 15:16:33.227204 835 shared_informer.go:377] "Caches are synced"1241machine # [ 21.315453] k3s[835]: I0913 15:16:33.227231 835 policy_source.go:248] refreshing policies1242machine # [ 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"1243machine # [ 21.351178] k3s[835]: E0913 15:16:33.267349 835 controller.go:95] Unable to perform initial Kubernetes service initialization: namespaces "default" not found1244machine # [ 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/UnhandledError1245machine # [ 21.392377] k3s[835]: I0913 15:16:33.310258 835 apf_controller.go:382] Running API Priority and Fairness config worker1246machine # [ 21.393283] k3s[835]: I0913 15:16:33.310312 835 apf_controller.go:385] Running API Priority and Fairness periodic rebalancing process1247machine # [ 21.401248] k3s[835]: I0913 15:16:33.319244 835 controller.go:667] quota admission added evaluator for: namespaces1248machine # [ 21.414068] k3s[835]: I0913 15:16:33.330628 835 cidrallocator.go:302] created ClusterIP allocator for Service CIDR 10.43.0.0/161249machine # [ 21.416127] k3s[835]: I0913 15:16:33.334204 835 default_servicecidr_controller.go:231] Setting default ServiceCIDR condition Ready to True1250machine # [ 21.425643] k3s[835]: I0913 15:16:33.343726 835 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161251machine # [ 21.432079] k3s[835]: I0913 15:16:33.350130 835 default_servicecidr_controller.go:231] Setting default ServiceCIDR condition Ready to True1252machine # [ 21.502370] k3s[835]: time="2026-09-13T15:16:33Z" level=info msg="containerd is now running"1253machine # [ 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"1254machine # [ 21.565429] k3s[835]: I0913 15:16:33.483477 835 controller.go:667] quota admission added evaluator for: leases.coordination.k8s.io1255machine # [ 22.202088] k3s[835]: I0913 15:16:34.119811 835 storage_scheduling.go:123] created PriorityClass system-node-critical with value 20000010001256machine # [ 22.210169] k3s[835]: I0913 15:16:34.128249 835 storage_scheduling.go:123] created PriorityClass system-cluster-critical with value 20000000001257machine # [ 22.211791] k3s[835]: I0913 15:16:34.128277 835 storage_scheduling.go:139] all system priority classes are created successfully or already exist.1258machine # [ 22.351109] k3s[835]: time="2026-09-13T15:16:34Z" level=info msg="Polling for API server readiness: GET /readyz failed: unknown"1259machine # [ 23.279917] k3s[835]: I0913 15:16:35.197672 835 controller.go:667] quota admission added evaluator for: roles.rbac.authorization.k8s.io1260machine # [ 23.320507] k3s[835]: I0913 15:16:35.238556 835 controller.go:667] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io1261machine # [ 23.460700] k3s[835]: I0913 15:16:35.378680 835 alloc.go:329] "allocated clusterIPs" service="default/kubernetes" clusterIPs={"IPv4":"10.43.0.1"}1262machine # [ 23.467381] k3s[835]: W0913 15:16:35.385293 835 lease.go:265] Resetting endpoints for master service "kubernetes" to [10.0.2.15]1263machine # [ 23.472909] k3s[835]: I0913 15:16:35.390798 835 controller.go:667] quota admission added evaluator for: endpoints1264machine # [ 23.478056] k3s[835]: I0913 15:16:35.396122 835 controller.go:667] quota admission added evaluator for: endpointslices.discovery.k8s.io1265machine # [ 24.358382] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating k3s-supervisor event broadcaster"1266machine # [ 24.366431] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Waiting for untainted node"1267machine # [ 24.367667] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Kube API server is now running"1268machine # [ 24.368830] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="k3s is up and running"1269machine # [ 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=Normal1270machine # [ 24.377316] systemd[1]: Started k3s service.1271machine # [ 24.377989] systemd[1]: Reached target Multi-User System.1272machine # [ 24.378802] systemd[1]: Startup finished in 971ms (kernel) + 3.947s (initrd) + 19.453s (userspace) = 24.372s.1273machine # [ 24.409679] k3s[835]: I0913 15:16:36.327645 835 controllermanager.go:189] "Starting" version="v1.35.8+k3s1"1274machine # [ 24.411153] k3s[835]: I0913 15:16:36.327671 835 controllermanager.go:191] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1275machine # [ 24.421662] k3s[835]: I0913 15:16:36.339570 835 secure_serving.go:211] Serving securely on 127.0.0.1:102571276machine # [ 24.423722] k3s[835]: I0913 15:16:36.340164 835 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1277machine # [ 24.425201] k3s[835]: I0913 15:16:36.340184 835 shared_informer.go:370] "Waiting for caches to sync"1278machine # [ 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"1279machine # [ 24.429338] k3s[835]: I0913 15:16:36.340314 835 tlsconfig.go:243] "Starting DynamicServingCertificateController"1280machine # [ 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"1281machine # [ 24.433369] k3s[835]: I0913 15:16:36.340397 835 shared_informer.go:370] "Waiting for caches to sync"1282machine # [ 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"1283machine # [ 24.437595] k3s[835]: I0913 15:16:36.340440 835 shared_informer.go:370] "Waiting for caches to sync"1284machine # [ 24.438839] k3s[835]: I0913 15:16:36.355439 835 controllermanager.go:627] "Warning: controller is disabled" controller="selinux-warning-controller"1285machine # [ 24.449560] k3s[835]: I0913 15:16:36.367605 835 controller.go:667] quota admission added evaluator for: serviceaccounts1286machine # [ 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"]1287machine # [ 24.476706] k3s[835]: I0913 15:16:36.392304 835 controllermanager.go:579] "Warning: skipping controller" controller="podcertificaterequest-cleaner-controller"1288machine # [ 24.518797] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating embedded CRD addons.k3s.cattle.io"1289machine # [ 24.525026] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating embedded CRD etcdsnapshotfiles.k3s.cattle.io"1290machine # [ 24.526592] k3s[835]: I0913 15:16:36.444671 835 shared_informer.go:377] "Caches are synced"1291machine # [ 24.528497] k3s[835]: I0913 15:16:36.446578 835 shared_informer.go:377] "Caches are synced"1292machine # [ 24.529796] k3s[835]: I0913 15:16:36.446651 835 shared_informer.go:377] "Caches are synced"1293machine # [ 24.536551] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating embedded CRD helmchartconfigs.helm.cattle.io"1294machine # [ 24.553074] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Creating embedded CRD helmcharts.helm.cattle.io"1295machine # [ 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"]1296machine # [ 24.559640] k3s[835]: I0913 15:16:36.475025 835 controllermanager.go:579] "Warning: skipping controller" controller="device-taint-eviction-controller"1297machine # [ 24.562034] k3s[835]: I0913 15:16:36.475037 835 controllermanager.go:579] "Warning: skipping controller" controller="storage-version-migrator-controller"1298machine # [ 24.568735] k3s[835]: I0913 15:16:36.486800 835 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1299machine # [ 24.585051] k3s[835]: I0913 15:16:36.503096 835 handler.go:304] Adding GroupVersion k3s.cattle.io v1 to ResourceManager1300machine # [ 24.587286] k3s[835]: I0913 15:16:36.503730 835 shared_informer.go:370] "Waiting for caches to sync"1301machine # [ 24.590188] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Waiting for CRD helmchartconfigs.helm.cattle.io to become available"1302machine # [ 24.599319] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Done waiting for CRD helmchartconfigs.helm.cattle.io to become available"1303machine # [ 24.600880] k3s[835]: time="2026-09-13T15:16:36Z" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available"1304machine # [ 24.602646] k3s[835]: I0913 15:16:36.518244 835 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1305machine # [ 24.614884] k3s[835]: I0913 15:16:36.532606 835 handler.go:304] Adding GroupVersion helm.cattle.io v1 to ResourceManager1306machine # [ 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"]1307machine # [ 24.647810] k3s[835]: I0913 15:16:36.562826 835 controllermanager.go:579] "Warning: skipping controller" controller="storageversion-garbage-collector-controller"1308machine: (finished: waiting for unit k3s.service, in 25.56 seconds)1309machine: waiting for unit rustfs-setup.service1310machine: (finished: waiting for unit rustfs-setup.service, in 0.08 seconds)1311machine: waiting for unit postgresql.service1312machine # [ 24.886543] k3s[835]: I0913 15:16:36.804498 835 shared_informer.go:377] "Caches are synced"1313machine: (finished: waiting for unit postgresql.service, in 0.12 seconds)1314subtest: chart deploys and becomes ready1315??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1316 File "/nix/store/wqwvv2w9ih8r1f0lsa0h3fqf91nblq7g-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391317machine: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s1318??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.1319 File "/nix/store/wqwvv2w9ih8r1f0lsa0h3fqf91nblq7g-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 391320machine # [ 25.119478] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available"1321machine # [ 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"1322machine # [ 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"1323machine # [ 25.126264] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml"1324machine # [ 25.129668] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml"1325machine # [ 25.131450] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml"1326machine # [ 25.133221] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml"1327machine # [ 25.134898] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/runtimes.yaml"1328machine # [ 25.136580] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml"1329machine # Error from server (NotFound): namespaces "niks3" not found1330machine # [ 25.240737] k3s[835]: I0913 15:16:37.158712 835 controllermanager.go:627] "Warning: controller is disabled" controller="bootstrap-signer-controller"1331machine # [ 25.392398] k3s[835]: I0913 15:16:37.310094 835 node_lifecycle_controller.go:419] "Controller will reconcile labels" logger="node-lifecycle-controller"1332machine # [ 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]"1333machine # [ 25.393451] k3s[835]: time="2026-09-13T15:16:37Z" level=info msg="Tunnel server egress proxy mode: agent"1334machine # [ 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]"1335machine # [ 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]"1336machine # [ 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.1337machine # Error from server (NotFound): namespaces "niks3" not found1338machine # [ 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"1339machine # [ 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"1340machine # [ 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"1341machine # [ 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"1342machine # [ 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"1343machine # [ 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"1344machine # [ 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"1345machine # [ 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"1346machine # [ 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"1347machine # [ 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"1348machine # [ 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"1349machine # [ 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"1350machine # [ 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"1351machine # [ 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"1352machine # [ 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"1353machine # [ 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"1354machine # [ 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"1355machine # [ 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"1356machine # [ 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"1357machine # [ 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"1358machine # [ 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"1359machine # [ 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"1360machine # [ 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"1361machine # [ 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"1362machine # [ 26.702451] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller"1363machine # [ 26.702635] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Creating deploy event broadcaster"1364machine # [ 26.709047] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Starting /v1, Kind=Node controller"1365machine # [ 26.711054] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Creating helm-controller event broadcaster"1366machine # [ 26.712412] k3s[835]: I0913 15:16:38.630493 835 controller.go:667] quota admission added evaluator for: addons.k3s.cattle.io1367machine # [ 26.736107] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Cluster dns configmap has been set successfully"1368machine # [ 26.739341] k3s[835]: time="2026-09-13T15:16:38Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1369machine # [ 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=Normal1370machine # [ 26.944457] k3s[835]: I0913 15:16:38.862458 835 controllermanager.go:627] "Warning: controller is disabled" controller="cloud-node-lifecycle-controller"1371machine # [ 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"]1372machine # [ 26.949636] k3s[835]: I0913 15:16:38.864439 835 controllermanager.go:579] "Warning: skipping controller" controller="kube-apiserver-serving-clustertrustbundle-publisher-controller"1373machine # [ 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=Normal1374machine # [ 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=Normal1375machine # [ 27.429079] k3s[835]: I0913 15:16:39.346348 835 serving.go:392] Generated self-signed cert in-memory1376machine # [ 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=Normal1377machine # [ 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=Normal1378machine # [ 27.650927] k3s[835]: I0913 15:16:39.568684 835 serving.go:392] Generated self-signed cert in-memory1379machine # [ 27.727145] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1380machine # Error from server (NotFound): namespaces "niks3" not found1381machine # [ 27.742059] k3s[835]: I0913 15:16:39.659128 835 controllermanager.go:627] "Warning: controller is disabled" controller="node-route-controller"1382machine # [ 27.808459] k3s[835]: I0913 15:16:39.726525 835 controllermanager.go:160] Version: v1.35.8+k3s11383machine # [ 27.812510] k3s[835]: I0913 15:16:39.730604 835 secure_serving.go:211] Serving securely on 127.0.0.1:102581384machine # [ 27.814056] k3s[835]: I0913 15:16:39.731990 835 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1385machine # [ 27.815569] k3s[835]: I0913 15:16:39.732184 835 shared_informer.go:370] "Waiting for caches to sync"1386machine # [ 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"1387machine # [ 27.818736] k3s[835]: I0913 15:16:39.732228 835 shared_informer.go:370] "Waiting for caches to sync"1388machine # [ 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"1389machine # [ 27.822349] k3s[835]: I0913 15:16:39.732259 835 shared_informer.go:370] "Waiting for caches to sync"1390machine # [ 27.823652] k3s[835]: I0913 15:16:39.732062 835 tlsconfig.go:243] "Starting DynamicServingCertificateController"1391machine # [ 27.824959] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Creating service-lb-controller event broadcaster"1392machine # [ 27.914897] k3s[835]: I0913 15:16:39.832959 835 shared_informer.go:377] "Caches are synced"1393machine # [ 27.917339] k3s[835]: I0913 15:16:39.833005 835 shared_informer.go:377] "Caches are synced"1394machine # [ 27.919042] k3s[835]: I0913 15:16:39.833068 835 shared_informer.go:377] "Caches are synced"1395machine # [ 27.934066] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding controller"1396machine # [ 27.938406] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting batch/v1, Kind=Job controller"1397machine # [ 27.939670] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=Secret controller"1398machine # [ 27.940803] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=ConfigMap controller"1399machine # [ 27.942166] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=ServiceAccount controller"1400machine # [ 27.945708] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller"1401machine # [ 27.947256] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller"1402machine # [ 28.053439] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=Node controller"1403machine # [ 28.060183] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting /v1, Kind=Pod controller"1404machine # [ 28.066603] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting apps/v1, Kind=DaemonSet controller"1405machine # [ 28.075057] k3s[835]: time="2026-09-13T15:16:39Z" level=info msg="Starting discovery.k8s.io/v1, Kind=EndpointSlice controller"1406machine # [ 28.076594] k3s[835]: W0913 15:16:39.991719 835 controllermanager.go:306] "node-route-controller" is disabled1407machine # [ 28.077864] k3s[835]: I0913 15:16:39.992383 835 controllermanager.go:329] Started "cloud-node-controller"1408machine # [ 28.079121] k3s[835]: I0913 15:16:39.992680 835 controllermanager.go:329] Started "cloud-node-lifecycle-controller"1409machine # [ 28.080409] k3s[835]: I0913 15:16:39.992972 835 node_controller.go:176] Sending events to api server.1410machine # [ 28.081549] k3s[835]: I0913 15:16:39.993015 835 node_lifecycle_controller.go:112] Sending events to api server1411machine # [ 28.082839] k3s[835]: I0913 15:16:39.993374 835 controllermanager.go:329] Started "service-lb-controller"1412machine # [ 28.084068] k3s[835]: I0913 15:16:39.993819 835 node_controller.go:185] Waiting for informer caches to sync1413machine # [ 28.085502] k3s[835]: I0913 15:16:39.994041 835 controller.go:235] Starting service controller1414machine # [ 28.086683] k3s[835]: I0913 15:16:39.994061 835 shared_informer.go:370] "Waiting for caches to sync"1415machine # [ 28.192718] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/klipper-helm:v0.13.3-build20260727"1416machine # [ 28.204706] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/klipper-helm@sha256:5425a2b4613d2458dbdff99218e8d487ebb59c20e7a941f061c0777070f0aac1"1417machine # [ 28.206699] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/klipper-lb:v0.4.17"1418machine # [ 28.210607] k3s[835]: I0913 15:16:40.128688 835 controller.go:667] quota admission added evaluator for: deployments.apps1419machine # [ 28.215549] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/klipper-lb@sha256:910944bb0bd94f060a82a56ca1ea1c577d3e49b3473a093a47a985f32e92d94a"1420machine # [ 28.217735] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/local-path-provisioner:v0.0.37"1421machine # [ 28.219342] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/local-path-provisioner@sha256:e757967a5ec338f6a9b371c5a9688bedaa8c3578ea3dd4db329ea0084be0a86f"1422machine # [ 28.223140] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-coredns-coredns:1.14.6"1423machine # [ 28.224640] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-coredns-coredns@sha256:900f9c109f7a33545d3c811516e8376df9019147b750f5ce3e254468769176ea"1424machine # [ 28.226960] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-library-busybox:1.37.0"1425machine # [ 28.228651] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-library-busybox@sha256:101b4afd76732482eff9b95cae5f94bcf295e521fbec4e01b69c5421f3f3f3e5"1426machine # [ 28.231297] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-library-traefik:3.7.8"1427machine # [ 28.233347] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-library-traefik@sha256:4299bbed850421258fc5448c2e0e6ad350981d4d335a68de11b92448aedbefe5"1428machine # [ 28.236444] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-metrics-server:v0.9.0"1429machine # [ 28.240868] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-metrics-server@sha256:d9862115e7c7881280d3d75ca26bda8ffc0fc213315979575bf23ce9826205c0"1430machine # [ 28.243302] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Imported docker.io/rancher/mirrored-pause:3.10.2"1431machine # [ 28.249219] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Tagged docker.io/rancher/mirrored-pause@sha256:f548e0e8e3dc1896ca956272154dde3314e8cc4fde0a57577ee9fa1c63f5baf4"1432machine # [ 28.277320] k3s[835]: I0913 15:16:40.195384 835 shared_informer.go:377] "Caches are synced"1433machine # [ 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"1434machine # [ 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"1435machine # [ 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"1436machine # [ 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.1437machine # [ 28.553227] k3s[835]: I0913 15:16:40.471304 835 server.go:521] "Kubelet version" kubeletVersion="v1.35.8+k3s1"1438machine # [ 28.554641] k3s[835]: I0913 15:16:40.471328 835 server.go:523] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1439machine # [ 28.556314] k3s[835]: I0913 15:16:40.471355 835 watchdog_linux.go:95] "Systemd watchdog is not enabled"1440machine # [ 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."1441machine # [ 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"1442machine # [ 28.562210] k3s[835]: I0913 15:16:40.480301 835 server.go:1414] "Using cgroup driver setting received from the CRI runtime" cgroupDriver="systemd"1443machine # [ 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 /"1444machine # [ 28.569568] k3s[835]: I0913 15:16:40.485528 835 server.go:832] "NoSwap is set due to memorySwapBehavior not specified" memorySwapBehavior="" FailSwapOn=false1445machine # [ 28.569887] k3s[835]: I0913 15:16:40.485775 835 container_manager_linux.go:272] "Container manager verified user specified cgroup-root exists" cgroupRoot=[]1446machine # [ 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}1447machine # [ 28.571387] k3s[835]: I0913 15:16:40.486032 835 topology_manager.go:143] "Creating topology manager with none policy"1448machine # [ 28.572801] k3s[835]: I0913 15:16:40.486046 835 container_manager_linux.go:308] "Creating device plugin manager"1449machine # [ 28.573508] k3s[835]: I0913 15:16:40.486113 835 container_manager_linux.go:317] "Creating Dynamic Resource Allocation (DRA) manager"1450machine # [ 28.575126] k3s[835]: I0913 15:16:40.490521 835 state_mem.go:41] "Initialized" logger="CPUManager state memory"1451machine # [ 28.575821] k3s[835]: I0913 15:16:40.490812 835 kubelet.go:482] "Attempting to sync node with API server"1452machine # [ 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"1453machine # [ 28.576894] k3s[835]: I0913 15:16:40.491006 835 kubelet.go:394] "Adding apiserver pod source"1454machine # [ 28.579767] k3s[835]: I0913 15:16:40.492225 835 apiserver.go:42] "Waiting for node sync before watching apiserver pods"1455machine # [ 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"1456machine # [ 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"1457machine # [ 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"1458machine # [ 28.606148] k3s[835]: I0913 15:16:40.524205 835 server.go:1252] "Started kubelet"1459machine # [ 28.609056] k3s[835]: I0913 15:16:40.526555 835 server.go:182] "Starting to listen" address="0.0.0.0" port=102501460machine # [ 28.610993] k3s[835]: I0913 15:16:40.529081 835 server.go:317] "Adding debug handlers to kubelet server"1461machine # [ 28.613470] k3s[835]: I0913 15:16:40.531523 835 ratelimit.go:56] "Setting rate limiting for endpoint" service="podresources" qps=100 burstTokens=101462machine # [ 28.615498] k3s[835]: I0913 15:16:40.533565 835 server_v1.go:49] "podresources" method="list" useActivePods=true1463machine # [ 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"1464machine # [ 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"1465machine # [ 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"1466machine # [ 28.627094] k3s[835]: I0913 15:16:40.545166 835 fs_resource_analyzer.go:69] "Starting FS ResourceAnalyzer"1467machine # [ 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"1468machine # [ 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"}1469machine # [ 28.642495] k3s[835]: I0913 15:16:40.557239 835 volume_manager.go:311] "Starting Kubelet Volume Manager"1470machine # [ 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"1471machine # [ 28.646149] k3s[835]: I0913 15:16:40.563790 835 desired_state_of_world_populator.go:146] "Desired state populator starts to run"1472machine # [ 28.649162] k3s[835]: I0913 15:16:40.563858 835 reconciler.go:29] "Reconciler: start to sync state"1473machine # [ 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 directory1474machine # [ 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=Normal1475machine # [ 28.666947] k3s[835]: I0913 15:16:40.584980 835 factory.go:223] Registration of the containerd container factory successfully1476machine # [ 28.669482] k3s[835]: I0913 15:16:40.585006 835 factory.go:223] Registration of the systemd container factory successfully1477machine # [ 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"1478machine # [ 28.711059] k3s[835]: I0913 15:16:40.629065 835 cpu_manager.go:225] "Starting" policy="none"1479machine # [ 28.712811] k3s[835]: I0913 15:16:40.629125 835 cpu_manager.go:226] "Reconciling" reconcilePeriod="10s"1480machine # [ 28.714483] k3s[835]: I0913 15:16:40.630419 835 state_mem.go:41] "Initialized" logger="CPUManager state checkpoint.CPUManager state memory"1481machine # [ 28.717255] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Unable to set control-plane role label: nodes \"machine\" not found"1482machine # [ 28.719431] k3s[835]: I0913 15:16:40.635302 835 controllermanager.go:627] "Warning: controller is disabled" controller="service-lb-controller"1483machine # [ 28.721908] k3s[835]: I0913 15:16:40.639753 835 policy_none.go:50] "Start"1484machine # [ 28.723336] k3s[835]: I0913 15:16:40.639775 835 memory_manager.go:187] "Starting memorymanager" policy="None"1485machine # [ 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"1486machine # [ 28.729423] k3s[835]: I0913 15:16:40.647500 835 policy_none.go:44] "Start"1487machine # [ 28.736904] systemd[1]: Created slice libcontainer container kubepods.slice.1488machine # [ 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"1489machine # [ 28.756964] systemd[1]: Created slice libcontainer container kubepods-burstable.slice.1490machine # [ 28.766680] systemd[1]: Created slice libcontainer container kubepods-besteffort.slice.1491machine # [ 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"1492machine # [ 28.779612] k3s[835]: I0913 15:16:40.693570 835 eviction_manager.go:194] "Eviction manager: starting control loop"1493machine # [ 28.782405] k3s[835]: I0913 15:16:40.693593 835 container_log_manager.go:146] "Initializing container log rotate workers" workers=1 monitorPeriod="10s"1494machine # [ 28.784788] k3s[835]: I0913 15:16:40.694997 835 plugin_manager.go:121] "Starting Kubelet Plugin Manager"1495machine # [ 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"1496machine # [ 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"1497machine # [ 28.880251] k3s[835]: I0913 15:16:40.798100 835 kubelet_node_status.go:74] "Attempting to register node" node="machine"1498machine # [ 28.906064] k3s[835]: I0913 15:16:40.823936 835 kubelet_node_status.go:77] "Successfully registered node" node="machine"1499machine # [ 28.920663] k3s[835]: I0913 15:16:40.836888 835 node_controller.go:429] Initializing node machine with cloud provider1500machine # [ 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, requeuing1501machine # [ 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"1502machine # [ 28.928153] k3s[835]: I0913 15:16:40.841485 835 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv4"1503machine # [ 28.930211] k3s[835]: I0913 15:16:40.843944 835 node_controller.go:429] Initializing node machine with cloud provider1504machine # [ 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, requeuing1505machine # [ 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"1506machine # [ 28.939557] k3s[835]: I0913 15:16:40.857550 835 node_controller.go:429] Initializing node machine with cloud provider1507machine # [ 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, requeuing1508machine # [ 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"1509machine # [ 28.951491] k3s[835]: I0913 15:16:40.868456 835 kubelet_network_linux.go:54] "Initialized iptables rules." protocol="IPv6"1510machine # [ 28.955166] k3s[835]: I0913 15:16:40.868480 835 status_manager.go:249] "Starting to sync pod status with apiserver"1511machine # [ 28.956585] k3s[835]: I0913 15:16:40.868510 835 kubelet.go:2506] "Starting kubelet main sync loop"1512machine # [ 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"1513machine # [ 28.960494] k3s[835]: I0913 15:16:40.878585 835 node_controller.go:429] Initializing node machine with cloud provider1514machine # [ 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, requeuing1515machine # [ 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"1516machine # [ 28.977507] k3s[835]: I0913 15:16:40.895603 835 node_controller.go:429] Initializing node machine with cloud provider1517machine # [ 28.984419] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Annotations and labels have been set successfully on node: machine"1518machine # [ 28.988222] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Synced coredns NodeHosts entries for machine"1519machine # [ 28.990230] k3s[835]: time="2026-09-13T15:16:40Z" level=info msg="Starting flannel with backend vxlan"1520machine # [ 29.050827] k3s[835]: I0913 15:16:40.968847 835 node_controller.go:474] Successfully initialized node machine with cloud provider1521machine # [ 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"1522machine # [ 29.068993] k3s[835]: I0913 15:16:40.987079 835 shared_informer.go:370] "Waiting for caches to sync"1523machine # [ 29.076068] k3s[835]: I0913 15:16:40.994124 835 shared_informer.go:370] "Waiting for caches to sync"1524machine # [ 29.077506] k3s[835]: I0913 15:16:40.995560 835 namespace_controller.go:202] "Starting namespace controller"1525machine # [ 29.080065] k3s[835]: I0913 15:16:40.996925 835 shared_informer.go:370] "Waiting for caches to sync"1526machine # [ 29.081316] k3s[835]: I0913 15:16:40.996963 835 ttl_controller.go:127] "Starting TTL controller"1527machine # [ 29.082413] k3s[835]: I0913 15:16:40.997006 835 shared_informer.go:370] "Waiting for caches to sync"1528machine # [ 29.083537] k3s[835]: I0913 15:16:40.997043 835 expand_controller.go:328] "Starting expand controller"1529machine # [ 29.084722] k3s[835]: I0913 15:16:40.997086 835 shared_informer.go:370] "Waiting for caches to sync"1530machine # [ 29.086054] k3s[835]: I0913 15:16:40.997122 835 controller.go:174] "Starting ephemeral volume controller"1531machine # [ 29.087234] k3s[835]: I0913 15:16:40.997161 835 shared_informer.go:370] "Waiting for caches to sync"1532machine # [ 29.088397] k3s[835]: I0913 15:16:40.997247 835 replica_set.go:241] "Starting controller" name="replicationcontroller"1533machine # [ 29.089722] k3s[835]: I0913 15:16:40.997278 835 shared_informer.go:370] "Waiting for caches to sync"1534machine # [ 29.090912] k3s[835]: I0913 15:16:40.997373 835 replica_set.go:241] "Starting controller" name="replicaset"1535machine # [ 29.092098] k3s[835]: I0913 15:16:40.997393 835 shared_informer.go:370] "Waiting for caches to sync"1536machine # [ 29.093224] k3s[835]: I0913 15:16:40.997427 835 disruption.go:458] "Sending events to api server."1537machine # [ 29.094341] k3s[835]: I0913 15:16:40.997514 835 disruption.go:465] "Starting disruption controller"1538machine # [ 29.095465] k3s[835]: I0913 15:16:40.997524 835 shared_informer.go:370] "Waiting for caches to sync"1539machine # [ 29.096613] k3s[835]: I0913 15:16:40.997634 835 vac_protection_controller.go:206] "Starting VAC protection controller"1540machine # [ 29.097932] k3s[835]: I0913 15:16:40.997652 835 shared_informer.go:370] "Waiting for caches to sync"1541machine # [ 29.099143] k3s[835]: I0913 15:16:40.997680 835 ttlafterfinished_controller.go:112] "Starting TTL after finished controller"1542machine # [ 29.100628] k3s[835]: I0913 15:16:40.997699 835 shared_informer.go:370] "Waiting for caches to sync"1543machine # [ 29.101797] k3s[835]: I0913 15:16:40.997977 835 job_controller.go:254] "Starting job controller"1544machine # [ 29.102909] k3s[835]: I0913 15:16:40.998023 835 shared_informer.go:370] "Waiting for caches to sync"1545machine # [ 29.107214] k3s[835]: I0913 15:16:40.998088 835 horizontal.go:204] "Starting HPA controller"1546machine # [ 29.108353] k3s[835]: I0913 15:16:40.998106 835 shared_informer.go:370] "Waiting for caches to sync"1547machine # [ 29.109585] k3s[835]: I0913 15:16:41.022390 835 certificate_controller.go:120] "Starting certificate controller" name="csrapproving"1548machine # [ 29.110995] k3s[835]: I0913 15:16:41.022421 835 shared_informer.go:370] "Waiting for caches to sync"1549machine # [ 29.112194] k3s[835]: I0913 15:16:41.022501 835 node_lifecycle_controller.go:453] "Sending events to api server"1550machine # [ 29.113547] k3s[835]: I0913 15:16:41.022539 835 node_lifecycle_controller.go:460] "Starting node controller"1551machine # [ 29.114760] k3s[835]: I0913 15:16:41.022548 835 shared_informer.go:370] "Waiting for caches to sync"1552machine # [ 29.115889] k3s[835]: I0913 15:16:41.022639 835 endpointslice_controller.go:283] "Starting endpoint slice controller"1553machine # [ 29.117224] k3s[835]: I0913 15:16:41.022693 835 shared_informer.go:370] "Waiting for caches to sync"1554machine # [ 29.118348] k3s[835]: I0913 15:16:41.022726 835 serviceaccounts_controller.go:117] "Starting service account controller"1555machine # [ 29.119672] k3s[835]: I0913 15:16:41.022744 835 shared_informer.go:370] "Waiting for caches to sync"1556machine # [ 29.120785] k3s[835]: I0913 15:16:41.023460 835 attach_detach_controller.go:335] "Starting attach detach controller"1557machine # [ 29.122091] k3s[835]: I0913 15:16:41.023484 835 shared_informer.go:370] "Waiting for caches to sync"1558machine # [ 29.123252] k3s[835]: I0913 15:16:41.023517 835 pvc_protection_controller.go:166] "Starting PVC protection controller"1559machine # [ 29.124836] k3s[835]: I0913 15:16:41.023534 835 shared_informer.go:370] "Waiting for caches to sync"1560machine # [ 29.126031] k3s[835]: I0913 15:16:41.023714 835 publisher.go:107] "Starting root CA cert publisher controller"1561machine # [ 29.127899] k3s[835]: I0913 15:16:41.023747 835 shared_informer.go:370] "Waiting for caches to sync"1562machine # [ 29.129507] k3s[835]: I0913 15:16:41.023866 835 controller.go:423] "Starting resource claim controller"1563machine # [ 29.131217] k3s[835]: I0913 15:16:41.023883 835 shared_informer.go:370] "Waiting for caches to sync"1564machine # [ 29.132836] k3s[835]: I0913 15:16:41.023917 835 taint_eviction.go:283] "Starting" controller="taint-eviction-controller"1565machine # [ 29.134671] k3s[835]: I0913 15:16:41.024105 835 taint_eviction.go:288] "Sending events to API server"1566machine # [ 29.135846] k3s[835]: I0913 15:16:41.024116 835 shared_informer.go:370] "Waiting for caches to sync"1567machine # [ 29.137590] k3s[835]: I0913 15:16:41.024752 835 deployment_controller.go:172] "Starting controller" controller="deployment"1568machine # [ 29.139697] k3s[835]: I0913 15:16:41.024773 835 shared_informer.go:370] "Waiting for caches to sync"1569machine # [ 29.141486] k3s[835]: I0913 15:16:41.043053 835 stateful_set.go:180] "Starting stateful set controller"1570machine # [ 29.145347] k3s[835]: I0913 15:16:41.043084 835 shared_informer.go:370] "Waiting for caches to sync"1571machine # [ 29.147045] k3s[835]: I0913 15:16:41.043294 835 legacy_serviceaccount_token_cleaner.go:103] "Starting legacy service account token cleaner controller"1572machine # [ 29.149409] k3s[835]: I0913 15:16:41.043308 835 shared_informer.go:370] "Waiting for caches to sync"1573machine # [ 29.151106] k3s[835]: I0913 15:16:41.043602 835 servicecidrs_controller.go:136] "Starting" controller="service-cidr-controller"1574machine # [ 29.152788] k3s[835]: I0913 15:16:41.043617 835 shared_informer.go:370] "Waiting for caches to sync"1575machine # [ 29.153894] k3s[835]: I0913 15:16:41.043810 835 endpoints_controller.go:193] "Starting endpoint controller"1576machine # [ 29.155127] k3s[835]: I0913 15:16:41.043823 835 shared_informer.go:370] "Waiting for caches to sync"1577machine # [ 29.156282] k3s[835]: I0913 15:16:41.044009 835 endpointslicemirroring_controller.go:226] "Starting EndpointSliceMirroring controller"1578machine # [ 29.157704] k3s[835]: I0913 15:16:41.044023 835 shared_informer.go:370] "Waiting for caches to sync"1579machine # [ 29.158830] k3s[835]: I0913 15:16:41.044378 835 daemon_controller.go:309] "Starting daemon sets controller"1580machine # [ 29.160053] k3s[835]: I0913 15:16:41.044395 835 shared_informer.go:370] "Waiting for caches to sync"1581machine # [ 29.161177] k3s[835]: I0913 15:16:41.044582 835 cleaner.go:83] "Starting CSR cleaner controller"1582machine # [ 29.162231] k3s[835]: I0913 15:16:41.045424 835 pv_controller_base.go:307] "Starting persistent volume controller"1583machine # [ 29.163430] k3s[835]: I0913 15:16:41.045441 835 shared_informer.go:370] "Waiting for caches to sync"1584machine # [ 29.164533] k3s[835]: I0913 15:16:41.045857 835 pv_protection_controller.go:81] "Starting PV protection controller"1585machine # [ 29.165834] k3s[835]: I0913 15:16:41.045872 835 shared_informer.go:370] "Waiting for caches to sync"1586machine # [ 29.166975] k3s[835]: I0913 15:16:41.046520 835 cronjob_controllerv2.go:143] "Starting cronjob controller v2"1587machine # [ 29.168305] k3s[835]: I0913 15:16:41.046537 835 shared_informer.go:370] "Waiting for caches to sync"1588machine # [ 29.169416] k3s[835]: I0913 15:16:41.047122 835 node_ipam_controller.go:142] "Starting ipam controller"1589machine # [ 29.170623] k3s[835]: I0913 15:16:41.047163 835 shared_informer.go:370] "Waiting for caches to sync"1590machine # [ 29.171820] k3s[835]: I0913 15:16:41.047485 835 gc_controller.go:98] "Starting GC controller"1591machine # [ 29.173526] k3s[835]: I0913 15:16:41.047499 835 shared_informer.go:370] "Waiting for caches to sync"1592machine # [ 29.174706] k3s[835]: I0913 15:16:41.047603 835 tokencleaner.go:117] "Starting token cleaner controller"1593machine # [ 29.175955] k3s[835]: I0913 15:16:41.047665 835 shared_informer.go:370] "Waiting for caches to sync"1594machine # [ 29.177105] k3s[835]: I0913 15:16:41.047753 835 clusterroleaggregation_controller.go:194] "Starting ClusterRoleAggregator controller"1595machine # [ 29.178614] k3s[835]: I0913 15:16:41.047764 835 shared_informer.go:370] "Waiting for caches to sync"1596machine # [ 29.179804] k3s[835]: I0913 15:16:41.050301 835 garbagecollector.go:141] "Starting controller" controller="garbagecollector"1597machine # [ 29.181144] k3s[835]: I0913 15:16:41.050341 835 shared_informer.go:370] "Waiting for caches to sync"1598machine # [ 29.182325] k3s[835]: I0913 15:16:41.050812 835 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-serving"1599machine # [ 29.183819] k3s[835]: I0913 15:16:41.050832 835 shared_informer.go:370] "Waiting for caches to sync"1600machine # [ 29.185030] k3s[835]: I0913 15:16:41.051081 835 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kubelet-client"1601machine # [ 29.186674] k3s[835]: I0913 15:16:41.051117 835 shared_informer.go:370] "Waiting for caches to sync"1602machine # [ 29.187877] k3s[835]: I0913 15:16:41.051365 835 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-kube-apiserver-client"1603machine # [ 29.189501] k3s[835]: I0913 15:16:41.051384 835 shared_informer.go:370] "Waiting for caches to sync"1604machine # [ 29.190607] k3s[835]: I0913 15:16:41.051652 835 certificate_controller.go:120] "Starting certificate controller" name="csrsigning-legacy-unknown"1605machine # [ 29.192870] k3s[835]: I0913 15:16:41.051671 835 shared_informer.go:370] "Waiting for caches to sync"1606machine # [ 29.194069] k3s[835]: I0913 15:16:41.054895 835 resource_quota_controller.go:297] "Starting resource quota controller"1607machine # [ 29.195440] k3s[835]: I0913 15:16:41.054926 835 shared_informer.go:370] "Waiting for caches to sync"1608machine # [ 29.196595] k3s[835]: I0913 15:16:41.059052 835 graph_builder.go:386] "Running" component="GraphBuilder"1609machine # [ 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"1610machine # [ 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"1611machine # [ 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"1612machine # [ 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"1613machine # [ 29.207021] k3s[835]: I0913 15:16:41.062552 835 resource_quota_monitor.go:309] "QuotaMonitor running"1614machine # [ 29.218061] k3s[835]: I0913 15:16:41.135555 835 server.go:173] "Starting Kubernetes Scheduler" version="v1.35.8+k3s1"1615machine # [ 29.219932] k3s[835]: I0913 15:16:41.135583 835 server.go:175] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1616machine # [ 29.238252] k3s[835]: I0913 15:16:41.156331 835 kubelet_node_status.go:427] "Fast updating node status as it just became ready"1617machine # [ 29.244051] k3s[835]: I0913 15:16:41.161354 835 shared_informer.go:370] "Waiting for caches to sync"1618machine # Error from server (NotFound): namespaces "niks3" not found1619machine # [ 29.275287] k3s[835]: I0913 15:16:41.193367 835 secure_serving.go:211] Serving securely on 127.0.0.1:102591620machine # [ 29.279281] k3s[835]: I0913 15:16:41.197374 835 requestheader_controller.go:180] Starting RequestHeaderAuthRequestController1621machine # [ 29.280743] k3s[835]: I0913 15:16:41.198839 835 shared_informer.go:370] "Waiting for caches to sync"1622machine # [ 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"1623machine # [ 29.284877] k3s[835]: I0913 15:16:41.202976 835 tlsconfig.go:243] "Starting DynamicServingCertificateController"1624machine # [ 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"1625machine # [ 29.291797] k3s[835]: I0913 15:16:41.209901 835 shared_informer.go:370] "Waiting for caches to sync"1626machine # [ 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"1627machine # [ 29.295180] k3s[835]: I0913 15:16:41.213286 835 shared_informer.go:370] "Waiting for caches to sync"1628machine # [ 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"1629machine # [ 29.322519] k3s[835]: I0913 15:16:41.240596 835 shared_informer.go:377] "Caches are synced"1630machine # [ 29.345479] k3s[835]: I0913 15:16:41.263568 835 shared_informer.go:377] "Caches are synced"1631machine # [ 29.349225] k3s[835]: I0913 15:16:41.267204 835 shared_informer.go:370] "Waiting for caches to sync"1632machine # [ 29.350704] k3s[835]: I0913 15:16:41.264461 835 shared_informer.go:377] "Caches are synced"1633machine # [ 29.358270] k3s[835]: I0913 15:16:41.276353 835 range_allocator.go:177] "Sending events to api server"1634machine # [ 29.359541] k3s[835]: I0913 15:16:41.276426 835 range_allocator.go:181] "Starting range CIDR allocator"1635machine # [ 29.360751] k3s[835]: I0913 15:16:41.276437 835 shared_informer.go:370] "Waiting for caches to sync"1636machine # [ 29.361928] k3s[835]: I0913 15:16:41.276450 835 shared_informer.go:377] "Caches are synced"1637machine # [ 29.382060] k3s[835]: I0913 15:16:41.299742 835 shared_informer.go:377] "Caches are synced"1638machine # [ 29.383243] k3s[835]: I0913 15:16:41.299803 835 shared_informer.go:377] "Caches are synced"1639machine # [ 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"]1640machine # [ 29.414063] k3s[835]: I0913 15:16:41.330699 835 shared_informer.go:377] "Caches are synced"1641machine # [ 29.415235] k3s[835]: I0913 15:16:41.330784 835 shared_informer.go:377] "Caches are synced"1642machine # [ 29.416398] k3s[835]: I0913 15:16:41.330842 835 shared_informer.go:377] "Caches are synced"1643machine # [ 29.425648] k3s[835]: I0913 15:16:41.343735 835 shared_informer.go:377] "Caches are synced"1644machine # [ 29.426877] k3s[835]: I0913 15:16:41.344504 835 shared_informer.go:377] "Caches are synced"1645machine # [ 29.427991] k3s[835]: I0913 15:16:41.345696 835 shared_informer.go:377] "Caches are synced"1646machine # [ 29.429089] k3s[835]: I0913 15:16:41.346034 835 shared_informer.go:377] "Caches are synced"1647machine # [ 29.430176] k3s[835]: I0913 15:16:41.347116 835 shared_informer.go:377] "Caches are synced"1648machine # [ 29.431249] k3s[835]: I0913 15:16:41.347640 835 shared_informer.go:377] "Caches are synced"1649machine # [ 29.432249] k3s[835]: I0913 15:16:41.348209 835 shared_informer.go:377] "Caches are synced"1650machine # [ 29.433354] k3s[835]: I0913 15:16:41.348390 835 shared_informer.go:377] "Caches are synced"1651machine # [ 29.434481] k3s[835]: I0913 15:16:41.351022 835 shared_informer.go:377] "Caches are synced"1652machine # [ 29.435575] k3s[835]: I0913 15:16:41.351227 835 shared_informer.go:377] "Caches are synced"1653machine # [ 29.436661] k3s[835]: I0913 15:16:41.351524 835 shared_informer.go:377] "Caches are synced"1654machine # [ 29.437735] k3s[835]: I0913 15:16:41.351838 835 shared_informer.go:377] "Caches are synced"1655machine # [ 29.438857] k3s[835]: I0913 15:16:41.355208 835 shared_informer.go:377] "Caches are synced"1656machine # [ 29.445651] k3s[835]: I0913 15:16:41.363734 835 shared_informer.go:377] "Caches are synced"1657machine # [ 29.471066] k3s[835]: I0913 15:16:41.388455 835 shared_informer.go:377] "Caches are synced"1658machine # [ 29.477494] k3s[835]: I0913 15:16:41.395567 835 shared_informer.go:377] "Caches are synced"1659machine # [ 29.479052] k3s[835]: I0913 15:16:41.397128 835 shared_informer.go:377] "Caches are synced"1660machine # [ 29.480182] k3s[835]: I0913 15:16:41.397203 835 shared_informer.go:377] "Caches are synced"1661machine # [ 29.481253] k3s[835]: I0913 15:16:41.397320 835 shared_informer.go:377] "Caches are synced"1662machine # [ 29.482334] k3s[835]: I0913 15:16:41.397474 835 shared_informer.go:377] "Caches are synced"1663machine # [ 29.483405] k3s[835]: I0913 15:16:41.397661 835 shared_informer.go:377] "Caches are synced"1664machine # [ 29.484508] k3s[835]: I0913 15:16:41.397709 835 shared_informer.go:377] "Caches are synced"1665machine # [ 29.485599] k3s[835]: I0913 15:16:41.397740 835 shared_informer.go:377] "Caches are synced"1666machine # [ 29.486697] k3s[835]: I0913 15:16:41.398064 835 shared_informer.go:377] "Caches are synced"1667machine # [ 29.487741] k3s[835]: I0913 15:16:41.398172 835 shared_informer.go:377] "Caches are synced"1668machine # [ 29.505097] k3s[835]: I0913 15:16:41.422479 835 shared_informer.go:377] "Caches are synced"1669machine # [ 29.506361] k3s[835]: I0913 15:16:41.422660 835 shared_informer.go:377] "Caches are synced"1670machine # [ 29.507635] k3s[835]: I0913 15:16:41.422741 835 node_lifecycle_controller.go:1234] "Initializing eviction metric for zone" zone=""1671machine # [ 29.509209] k3s[835]: I0913 15:16:41.422809 835 shared_informer.go:377] "Caches are synced"1672machine # [ 29.528073] k3s[835]: I0913 15:16:41.445736 835 shared_informer.go:377] "Caches are synced"1673machine # [ 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"1674machine # [ 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"1675machine # [ 29.532574] k3s[835]: I0913 15:16:41.445993 835 shared_informer.go:377] "Caches are synced"1676machine # [ 29.533631] k3s[835]: I0913 15:16:41.446038 835 topologycache.go:237] "Can't get CPU or zone information for node" node="machine"1677machine # [ 29.535156] k3s[835]: I0913 15:16:41.446450 835 shared_informer.go:377] "Caches are synced"1678machine # [ 29.536220] k3s[835]: I0913 15:16:41.446531 835 shared_informer.go:377] "Caches are synced"1679machine # [ 29.537241] k3s[835]: I0913 15:16:41.446815 835 shared_informer.go:377] "Caches are synced"1680machine # [ 29.538344] k3s[835]: I0913 15:16:41.446931 835 shared_informer.go:377] "Caches are synced"1681machine # [ 29.539435] k3s[835]: I0913 15:16:41.447453 835 shared_informer.go:377] "Caches are synced"1682machine # [ 29.540526] k3s[835]: I0913 15:16:41.447628 835 shared_informer.go:377] "Caches are synced"1683machine # [ 29.541566] k3s[835]: I0913 15:16:41.447803 835 shared_informer.go:377] "Caches are synced"1684machine # [ 29.579865] k3s[835]: I0913 15:16:41.496702 835 apiserver.go:52] "Watching apiserver"1685machine # [ 29.599696] k3s[835]: I0913 15:16:41.517764 835 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161686machine # [ 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=Normal1687machine # [ 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=Normal1688machine # [ 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=Normal1689machine # [ 29.625560] k3s[835]: I0913 15:16:41.543457 835 cidrallocator.go:278] updated ClusterIP allocator for Service CIDR 10.43.0.0/161690machine # [ 29.645811] k3s[835]: I0913 15:16:41.563877 835 desired_state_of_world_populator.go:154] "Finished populating initial desired state of world"1691machine # [ 29.667870] k3s[835]: I0913 15:16:41.585404 835 controller.go:667] quota admission added evaluator for: helmcharts.helm.cattle.io1692machine # [ 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=Normal1693machine # [ 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=Normal1694machine # [ 29.715741] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Adding node OwnerReference to node-password secret machine.node-password.k3s"1695machine # [ 29.718162] k3s[835]: time="2026-09-13T15:16:41Z" level=info msg="Labels and annotations have been set successfully on node: machine"1696machine # [ 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=Normal1697machine # [ 29.761863] k3s[835]: I0913 15:16:41.679940 835 controller.go:667] quota admission added evaluator for: jobs.batch1698machine # [ 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"]1699machine # [ 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`"1700machine # [ 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=Normal1701machine # [ 29.942127] k3s[835]: I0913 15:16:41.860171 835 server.go:264] "kube-proxy running in dual-stack mode" primary ipFamily="IPv4"1702machine # [ 29.944481] k3s[835]: I0913 15:16:41.860212 835 server_linux.go:136] "Using iptables Proxier"1703machine # [ 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=Normal1704machine # [ 29.965057] k3s[835]: I0913 15:16:41.882790 835 controller.go:667] quota admission added evaluator for: replicasets.apps1705machine # [ 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"1706machine # [ 30.024881] k3s[835]: I0913 15:16:41.942935 835 server.go:529] "Version info" version="v1.35.8+k3s1"1707machine # [ 30.026220] k3s[835]: I0913 15:16:41.942972 835 server.go:531] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""1708machine # [ 30.027890] k3s[835]: I0913 15:16:41.944424 835 config.go:200] "Starting service config controller"1709machine # [ 30.029948] k3s[835]: I0913 15:16:41.944443 835 shared_informer.go:349] "Waiting for caches to sync" controller="service config"1710machine # [ 30.031737] k3s[835]: I0913 15:16:41.944472 835 config.go:106] "Starting endpoint slice config controller"1711machine # [ 30.033795] k3s[835]: I0913 15:16:41.944486 835 shared_informer.go:349] "Waiting for caches to sync" controller="endpoint slice config"1712machine # [ 30.036079] k3s[835]: I0913 15:16:41.944513 835 config.go:403] "Starting serviceCIDR config controller"1713machine # [ 30.038084] k3s[835]: I0913 15:16:41.944525 835 shared_informer.go:349] "Waiting for caches to sync" controller="serviceCIDR config"1714machine # [ 30.039725] k3s[835]: I0913 15:16:41.944962 835 config.go:309] "Starting node config controller"1715machine # [ 30.041568] k3s[835]: I0913 15:16:41.944975 835 shared_informer.go:349] "Waiting for caches to sync" controller="node config"1716machine # [ 30.043227] k3s[835]: I0913 15:16:41.944986 835 shared_informer.go:356] "Caches are synced" controller="node config"1717machine # [ 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=Normal1718machine # [ 30.155561] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Flannel found PodCIDR assigned for node machine"1719machine # [ 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"1720machine # [ 30.159136] k3s[835]: I0913 15:16:42.074656 835 kube.go:139] Waiting 10m0s for node controller to sync1721machine # [ 30.160631] k3s[835]: I0913 15:16:42.074771 835 kube.go:537] Starting kube subnet manager1722machine # [ 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=Normal1723machine # [ 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=Normal1724machine # [ 30.227437] k3s[835]: I0913 15:16:42.145485 835 shared_informer.go:356] "Caches are synced" controller="serviceCIDR config"1725machine # [ 30.227821] k3s[835]: I0913 15:16:42.145559 835 shared_informer.go:356] "Caches are synced" controller="service config"1726machine # [ 30.228377] k3s[835]: I0913 15:16:42.145586 835 shared_informer.go:356] "Caches are synced" controller="endpoint slice config"1727machine # [ 30.361490] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Tunnel authorizer set Kubelet Port 0.0.0.0:10250"1728machine # [ 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"1729machine # [ 30.434925] k3s[835]: time="2026-09-13T15:16:42Z" level=info msg="Tagged docker.io/library/niks3-server@sha256:c72a0c846cd0f611b79ee797431374f3eb618c301ca7a268547b626fe83377df"1730machine # [ 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"1731machine # Error from server (NotFound): namespaces "niks3" not found1732machine # [ 30.649298] k3s[835]: I0913 15:16:42.567302 835 shared_informer.go:377] "Caches are synced"1733machine # [ 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"1734machine # [ 30.752397] systemd[1]: Created slice libcontainer container kubepods-burstable-pod338ed778_f4f8_41b0_8078_3ebdce579742.slice.1735machine # [ 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"1736machine # [ 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"1737machine # [ 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"1738machine # [ 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"1739machine # [ 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"1740machine # [ 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"1741machine # [ 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"1742machine # [ 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"1743machine # [ 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"1744machine # [ 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"1745machine # [ 30.816516] k3s[835]: I0913 15:16:42.684518 835 shared_informer.go:377] "Caches are synced"1746machine # [ 30.817880] k3s[835]: I0913 15:16:42.686248 835 garbagecollector.go:166] "Garbage collector: all resource monitors have synced"1747machine # [ 30.819357] k3s[835]: I0913 15:16:42.686261 835 garbagecollector.go:169] "Proceeding to collect garbage"1748machine # [ 30.820590] systemd[1]: Created slice libcontainer container kubepods-burstable-podc7fa4117_0e7f_496c_8354_68d774a9432f.slice.1749machine # [ 31.157629] k3s[835]: I0913 15:16:43.075339 835 kube.go:163] Node controller sync successful1750machine # [ 31.159024] k3s[835]: I0913 15:16:43.075420 835 vxlan.go:128] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false1751machine # [ 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"}1752machine # [ 31.230498] k3s[835]: I0913 15:16:43.148080 835 iptables.go:50] Starting flannel in iptables mode...1753machine # [ 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"1754machine # [ 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"1755machine # [ 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"1756machine # [ 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"1757machine # [ 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 rules1758machine # [ 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]1759machine # [ 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"1760machine # [ 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"1761machine # [ 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"1762machine # [ 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"1763machine # [ 31.315918] (udev-worker)[1228]: Network interface NamePolicy= disabled on kernel command line.1764machine # [ 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"1765machine # [ 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"1766machine # [ 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"1767machine # [ 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"1768machine # [ 31.367296] dhcpcd[647]: flannel.1: IAID a5:20:5e:8d1769machine # [ 31.367470] dhcpcd[647]: flannel.1: adding address fe80::f4ea:a5ff:fe20:5e8d1770machine # [ 31.392339] k3s[835]: I0913 15:16:43.310373 835 iptables.go:111] Setting up masking rules1771machine # [ 31.419371] k3s[835]: I0913 15:16:43.337385 835 iptables.go:212] Changing default FORWARD chain policy to ACCEPT1772machine # [ 31.437436] k3s[835]: time="2026-09-13T15:16:43Z" level=info msg="Wrote flannel subnet file to /run/flannel/subnet.env"1773machine # [ 31.437720] k3s[835]: time="2026-09-13T15:16:43Z" level=info msg="Running flannel backend"1774machine # [ 31.438190] k3s[835]: I0913 15:16:43.355553 835 vxlan_network.go:68] watching for new subnet leases1775machine # [ 31.438628] k3s[835]: I0913 15:16:43.355574 835 vxlan_network.go:115] starting vxlan device watcher1776machine # [ 31.514469] k3s[835]: I0913 15:16:43.432507 835 iptables.go:358] bootstrap done1777machine # [ 31.556881] k3s[835]: I0913 15:16:43.474926 835 iptables.go:358] bootstrap done1778machine # Error from server (NotFound): namespaces "niks3" not found1779machine # [ 32.385464] dhcpcd[647]: flannel.1: soliciting an IPv6 router1780machine # Error from server (NotFound): namespaces "niks3" not found1781machine # [ 33.023381] dhcpcd[647]: flannel.1: soliciting a DHCP lease1782machine # [ 33.643962] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Started tunnel to 10.0.2.15:6443"1783machine # [ 33.646314] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Stopped tunnel to 127.0.0.1:6443"1784machine # [ 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"1785machine # [ 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"1786machine # [ 33.652443] k3s[835]: time="2026-09-13T15:16:45Z" level=info msg="Handling backend connection request [machine]"1787machine # [ 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"1788machine # [ 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"1789machine # [ 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"1790machine # Error from server (NotFound): namespaces "niks3" not found1791machine # Error from server (NotFound): namespaces "niks3" not found1792machine # Error from server (NotFound): namespaces "niks3" not found1793machine # Error from server (NotFound): namespaces "niks3" not found1794machine # [ 38.025936] dhcpcd[647]: flannel.1: probing for an IPv4LL address1795machine # Error from server (NotFound): namespaces "niks3" not found1796machine # [ 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"1797machine # [ 39.377605] k3s[835]: I0913 15:16:51.293327 835 kubelet_network.go:47] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="10.42.0.0/24"1798machine # [ 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"1799machine # [ 40.353239] k3s[835]: I0913 15:16:52.268578 835 network_policy_controller.go:164] Starting network policy controller1800machine # Error from server (NotFound): namespaces "niks3" not found1801machine # [ 40.770469] k3s[835]: I0913 15:16:52.688231 835 network_policy_controller.go:179] Starting network policy controller full sync goroutine1802machine # Error from server (NotFound): namespaces "niks3" not found1803machine # Error from server (NotFound): namespaces "niks3" not found1804machine # [ 43.166498] dhcpcd[647]: flannel.1: using IPv4LL address 169.254.76.1231805machine # [ 43.166926] dhcpcd[647]: flannel.1: adding route to 169.254.0.0/161806machine # Error from server (NotFound): namespaces "niks3" not found1807machine # [ 44.388852] dhcpcd[647]: flannel.1: no IPv6 Routers available1808machine # [ 45.181736] cni0: port 1(veth25394c81) entered blocking state1809machine # [ 45.182506] cni0: port 1(veth25394c81) entered disabled state1810machine # [ 45.183343] veth25394c81: entered allmulticast mode1811machine # [ 45.184043] veth25394c81: entered promiscuous mode1812machine # [ 45.197755] cni0: port 1(veth25394c81) entered blocking state1813machine # [ 45.198371] cni0: port 1(veth25394c81) entered forwarding state1814machine # [ 45.095869] (udev-worker)[1578]: Network interface NamePolicy= disabled on kernel command line.1815machine # [ 45.100236] (udev-worker)[1580]: Network interface NamePolicy= disabled on kernel command line.1816machine # [ 45.133741] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount59189901.mount: Deactivated successfully.1817machine # [ 45.147753] dhcpcd[647]: veth25394c81: IAID ff:bb:b7:421818machine # [ 45.149025] dhcpcd[647]: veth25394c81: adding address fe80::5008:ffff:febb:b7421819machine # [ 45.262290] systemd[1]: Started libcontainer container 745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573.1820machine # Error from server (NotFound): namespaces "niks3" not found1821machine # [ 45.577789] dhcpcd[647]: veth25394c81: soliciting a DHCP lease1822machine # [ 46.140732] cni0: port 2(vethd0a1dbe8) entered blocking state1823machine # [ 46.142115] cni0: port 2(vethd0a1dbe8) entered disabled state1824machine # [ 46.142708] vethd0a1dbe8: entered allmulticast mode1825machine # [ 46.144290] vethd0a1dbe8: entered promiscuous mode1826machine # [ 46.163144] cni0: port 2(vethd0a1dbe8) entered blocking state1827machine # [ 46.163773] cni0: port 2(vethd0a1dbe8) entered forwarding state1828machine # [ 46.040595] dhcpcd[647]: vethd0a1dbe8: IAID 1d:af:7c:9b1829machine # [ 46.041902] dhcpcd[647]: vethd0a1dbe8: adding address fe80::7c0a:1dff:feaf:7c9b1830machine # [ 46.171815] systemd[1]: Started libcontainer container 6ce343837467d6f143c68f611ef8a0d234bc1ff22015ccc79d1d160814b6944c.1831machine # [ 46.305535] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount3329550324.mount: Deactivated successfully.1832machine # [ 46.572688] systemd[1]: Started libcontainer container 8edf2bf25400367b2fd084d66aa9f9c19f4ce0d87e6def3a7c5aa8918e5110f5.1833machine # Error from server (NotFound): namespaces "niks3" not found1834machine # [ 46.839396] dhcpcd[647]: vethd0a1dbe8: soliciting a DHCP lease1835machine # [ 46.908518] dhcpcd[647]: veth25394c81: soliciting an IPv6 router1836machine # [ 47.298465] systemd[1]: Started libcontainer container 7bacd83175a6339604995527c8020a771d82ccb926174a794110b73066cca1aa.1837machine # [ 47.443107] dhcpcd[647]: vethd0a1dbe8: soliciting an IPv6 router1838machine # [ 47.716709] k3s[835]: I0913 15:16:59.634360 835 alloc.go:329] "allocated clusterIPs" service="niks3/niks3" clusterIPs={"IPv4":"10.43.23.207"}1839machine # [ 47.744071] k3s[835]: I0913 15:16:59.661888 835 controller.go:667] quota admission added evaluator for: cronjobs.batch1840machine # [ 47.771443] systemd[1]: cri-containerd-8edf2bf25400367b2fd084d66aa9f9c19f4ce0d87e6def3a7c5aa8918e5110f5.scope: Deactivated successfully.1841machine # [ 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.1842machine # [ 47.823455] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-8edf2bf25400367b2fd084d66aa9f9c19f4ce0d87e6def3a7c5aa8918e5110f5-rootfs.mount: Deactivated successfully.1843machine # [ 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"1844machine # [ 48.175439] systemd[1]: Created slice libcontainer container kubepods-besteffort-poddf8cb12e_8605_45c8_85c2_c28ea00f2ebe.slice.1845machine # [ 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"1846machine # [ 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"1847machine # [ 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"1848machine # [ 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"1849machine # [ 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"1850machine # [ 48.980581] cni0: port 3(veth73adb661) entered blocking state1851machine # [ 48.982274] cni0: port 3(veth73adb661) entered disabled state1852machine # [ 48.983234] veth73adb661: entered allmulticast mode1853machine # [ 48.984077] veth73adb661: entered promiscuous mode1854machine # [ 48.996153] cni0: port 3(veth73adb661) entered blocking state1855machine # [ 48.996737] cni0: port 3(veth73adb661) entered forwarding state1856machine # [ 48.924958] (udev-worker)[2020]: Network interface NamePolicy= disabled on kernel command line.1857machine # [ 48.974450] systemd[1]: Started libcontainer container ad378d80a00399a96028e67eab97a9a40c49c6bdbdc9b2c2ad0e5678fdaf1497.1858machine # [ 48.978262] dhcpcd[647]: veth73adb661: IAID 8c:a0:7d:571859machine # [ 48.978643] dhcpcd[647]: veth73adb661: adding address fe80::909d:8cff:fea0:7d571860machine # [ 49.113507] systemd[1]: cri-containerd-745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573.scope: Deactivated successfully.1861machine # [ 49.521306] cni0: port 1(veth25394c81) entered disabled state1862machine # [ 49.370510] dhcpcd[647]: veth25394c81: carrier lost1863machine # [ 49.523498] veth25394c81 (unregistering): left allmulticast mode1864machine # [ 49.524303] veth25394c81 (unregistering): left promiscuous mode1865machine # [ 49.525172] cni0: port 1(veth25394c81) entered disabled state1866machine # [ 49.416292] systemd[1]: Started libcontainer container 6b040244f348e35c0a61630e8848246d7ae5629006d1479872714d24ff7d8b1d.1867machine # [ 49.439226] dhcpcd[647]: veth25394c81: deleting address fe80::5008:ffff:febb:b7421868machine # [ 49.512887] postgres[2182]: [2182] ERROR: relation "goose_db_version" does not exist at character 361869machine # [ 49.513121] postgres[2182]: [2182] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1870machine # [ 49.522278] dhcpcd[647]: veth25394c81: removing interface1871machine # [ 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\") "1872machine # [ 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\") "1873machine # [ 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\") "1874machine # [ 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\") "1875machine # [ 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\") "1876machine # [ 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\") "1877machine # [ 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\") "1878machine # [ 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 ""1879machine # [ 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 ""1880machine # [ 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 ""1881machine # [ 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 ""1882machine # [ 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 ""1883machine # [ 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 ""1884machine # [ 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 ""1885machine # [ 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 \"\""1886machine # [ 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 \"\""1887machine # [ 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 \"\""1888machine # [ 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 \"\""1889machine # [ 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 \"\""1890machine # [ 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 \"\""1891machine # [ 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 \"\""1892machine # [ 49.664678] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573-rootfs.mount: Deactivated successfully.1893machine # [ 49.665122] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573-shm.mount: Deactivated successfully.1894machine # [ 49.665786] systemd[1]: run-netns-cni\x2dccffcf46\x2dced9\x2dea60\x2d3a20\x2d5a7fae535872.mount: Deactivated successfully.1895machine # [ 49.667791] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eprojected-kube\x2dapi\x2daccess\x2dkqlm2.mount: Deactivated successfully.1896machine # [ 49.668552] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eprojected-values.mount: Deactivated successfully.1897machine # [ 49.668953] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dcache.mount: Deactivated successfully.1898machine # [ 49.669583] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dhelm.mount: Deactivated successfully.1899machine # [ 49.669983] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eempty\x2ddir-tmp.mount: Deactivated successfully.1900machine # [ 49.672104] systemd[1]: var-lib-kubelet-pods-338ed778\x2df4f8\x2d41b0\x2d8078\x2d3ebdce579742-volumes-kubernetes.io\x7eempty\x2ddir-klipper\x2dconfig.mount: Deactivated successfully.1901machine # [ 49.852500] dhcpcd[647]: veth73adb661: soliciting a DHCP lease1902machine # [ 50.124748] k3s[835]: I0913 15:17:02.042749 835 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="745fd814fba1ff1cacb3b182b3ca89d178adbd5e1441901f182999ecbae82573"1903machine # [ 50.133287] systemd[1]: Removed slice libcontainer container kubepods-burstable-pod338ed778_f4f8_41b0_8078_3ebdce579742.slice.1904machine # [ 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.1905machine # [ 50.354621] dhcpcd[647]: veth73adb661: soliciting an IPv6 router1906machine # [ 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"1907machine # [ 51.840499] dhcpcd[647]: vethd0a1dbe8: probing for an IPv4LL address1908machine: (finished: waiting for success: kubectl -n niks3 rollout status deployment niks3 --timeout=10s, in 29.34 seconds)1909machine: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true1910machine: (finished: must succeed: kubectl -n niks3 get deployment niks3 -o jsonpath='{.metadata.annotations.reloader\.stakater\.com/auto}' | grep true, in 0.19 seconds)1911machine: waiting for success: curl -sf http://localhost:30051/readyz | grep OK1912machine: (finished: waiting for success: curl -sf http://localhost:30051/readyz | grep OK, in 0.10 seconds)1913(finished: subtest: chart deploys and becomes ready, in 29.62 seconds)1914machine: waiting for success: kubectl -n ci get sa builder1915machine: (finished: waiting for success: kubectl -n ci get sa builder, in 0.22 seconds)1916machine: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt1917machine # [ 54.853824] dhcpcd[647]: veth73adb661: probing for an IPv4LL address1918machine: (finished: must succeed: kubectl -n ci create token builder --audience niks3 > /tmp/builder.jwt, in 0.22 seconds)1919machine: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt1920machine: (finished: must succeed: kubectl -n ci create token intruder --audience niks3 > /tmp/intruder.jwt, in 0.20 seconds)1921machine: must succeed: readlink -f /run/current-system/sw/bin/niks31922machine: (finished: must succeed: readlink -f /run/current-system/sw/bin/niks3, in 0.04 seconds)1923subtest: allowed service account can push via workload identity1924machine: 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>&11925machine # [ 56.932145] dhcpcd[647]: vethd0a1dbe8: using IPv4LL address 169.254.247.121926machine # [ 56.933747] dhcpcd[647]: vethd0a1dbe8: adding route to 169.254.0.0/161927machine: (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)1928machine: must succeed: curl -sf -H 'Authorization: Bearer test-token-that-is-at-least-36-characters-long' -I http://localhost:30051/api/objects/69rx9yid472ww68bbf95nndvq8zi96ws.narinfo1929machine: (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)1930(finished: subtest: allowed service account can push via workload identity, in 2.12 seconds)1931subtest: write scope does not grant admin1932machine: must succeed: curl -s -o /dev/null -w '%{http_code}' -H "Authorization: Bearer $(cat /tmp/builder.jwt)" http://localhost:30051/api/gc/status1933machine: (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)1934(finished: subtest: write scope does not grant admin, in 0.07 seconds)1935subtest: other service accounts are rejected1936machine: 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>&11937machine: (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)1938(finished: subtest: other service accounts are rejected, in 0.23 seconds)1939subtest: gc cronjob runs against the service1940machine: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual1941machine: (finished: must succeed: kubectl -n niks3 create job --from=cronjob/niks3-gc gc-manual, in 0.20 seconds)1942machine: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s1943machine # [ 57.827323] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod5d9078a5_20d7_430c_8f80_f59e5ea8999e.slice.1944machine # [ 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"1945machine # [ 58.337740] cni0: port 1(veth54666bbd) entered blocking state1946machine # [ 58.338555] cni0: port 1(veth54666bbd) entered disabled state1947machine # [ 58.339578] veth54666bbd: entered allmulticast mode1948machine # [ 58.340359] veth54666bbd: entered promiscuous mode1949machine # [ 58.350896] cni0: port 1(veth54666bbd) entered blocking state1950machine # [ 58.351518] cni0: port 1(veth54666bbd) entered forwarding state1951machine # [ 58.283601] (udev-worker)[2495]: Network interface NamePolicy= disabled on kernel command line.1952machine # [ 58.329644] systemd[1]: Started libcontainer container 743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e.1953machine # [ 58.344371] dhcpcd[647]: veth54666bbd: IAID 0e:da:21:351954machine # [ 58.344789] dhcpcd[647]: veth54666bbd: adding address fe80::a090:eff:feda:21351955machine # [ 58.459480] systemd[1]: Started libcontainer container 4d7c86d30df82ad592449aec4b6d0c195e79ad7fea9e5a0f1034c7e59f002337.1956machine # [ 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"1957machine # [ 59.183315] dhcpcd[647]: veth54666bbd: soliciting a DHCP lease1958machine # [ 59.446202] dhcpcd[647]: vethd0a1dbe8: no IPv6 Routers available1959machine # [ 59.912825] dhcpcd[647]: veth73adb661: using IPv4LL address 169.254.119.1841960machine # [ 59.916317] dhcpcd[647]: veth73adb661: adding route to 169.254.0.0/161961machine # [ 60.536711] systemd[1]: cri-containerd-4d7c86d30df82ad592449aec4b6d0c195e79ad7fea9e5a0f1034c7e59f002337.scope: Deactivated successfully.1962machine # [ 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.1963machine # [ 60.575619] dhcpcd[647]: veth54666bbd: soliciting an IPv6 router1964machine # [ 60.607959] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-4d7c86d30df82ad592449aec4b6d0c195e79ad7fea9e5a0f1034c7e59f002337-rootfs.mount: Deactivated successfully.1965machine # [ 62.197660] systemd[1]: cri-containerd-743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e.scope: Deactivated successfully.1966machine # [ 62.250296] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e-rootfs.mount: Deactivated successfully.1967machine # [ 62.287178] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e-shm.mount: Deactivated successfully.1968machine # [ 62.501187] cni0: port 1(veth54666bbd) entered disabled state1969machine # [ 62.350625] dhcpcd[647]: veth54666bbd: carrier lost1970machine # [ 62.503754] veth54666bbd (unregistering): left allmulticast mode1971machine # [ 62.504587] veth54666bbd (unregistering): left promiscuous mode1972machine # [ 62.505595] cni0: port 1(veth54666bbd) entered disabled state1973machine # [ 62.376425] systemd[1]: run-netns-cni\x2d7bdec847\x2d01cf\x2d0264\x2d364b\x2de25b11663dd9.mount: Deactivated successfully.1974machine # [ 62.417100] dhcpcd[647]: veth54666bbd: deleting address fe80::a090:eff:feda:21351975machine # [ 62.487252] dhcpcd[647]: veth73adb661: no IPv6 Routers available1976machine # [ 62.487444] dhcpcd[647]: veth54666bbd: removing interface1977machine # [ 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\") "1978machine # [ 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 ""1979machine # [ 62.576767] systemd[1]: var-lib-kubelet-pods-5d9078a5\x2d20d7\x2d430c\x2d8f80\x2df59e5ea8999e-volumes-kubernetes.io\x7esecret-token.mount: Deactivated successfully.1980machine # [ 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 \"\""1981machine # [ 62.974268] systemd[1]: Removed slice libcontainer container kubepods-besteffort-pod5d9078a5_20d7_430c_8f80_f59e5ea8999e.slice.1982machine # [ 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.1983machine # [ 63.171885] k3s[835]: I0913 15:17:15.089816 835 pod_container_deletor.go:80] "Container not found in pod's containers" containerID="743e69b4ab2cb3e40af0bf9a82d121b432f50c3d5239f2bf65e02f211a268b8e"1984machine: (finished: waiting for success: kubectl -n niks3 wait --for=condition=complete job/gc-manual --timeout=10s, in 5.45 seconds)1985(finished: subtest: gc cronjob runs against the service, in 5.65 seconds)1986subtest: helm test hook passes1987machine: must succeed: helm test -n niks3 niks3 --timeout 2m >&21988machine # [ 64.332291] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod04539781_8855_49af_a880_e41013701b38.slice.1989machine # [ 64.525904] cni0: port 1(vethc5645dd1) entered blocking state1990machine # [ 64.527317] cni0: port 1(vethc5645dd1) entered disabled state1991machine # [ 64.528456] vethc5645dd1: entered allmulticast mode1992machine # [ 64.529386] vethc5645dd1: entered promiscuous mode1993machine # [ 64.380044] (udev-worker)[2709]: Network interface NamePolicy= disabled on kernel command line.1994machine # [ 64.542536] cni0: port 1(vethc5645dd1) entered blocking state1995machine # [ 64.543212] cni0: port 1(vethc5645dd1) entered forwarding state1996machine # [ 64.431762] dhcpcd[647]: vethc5645dd1: IAID 16:24:fd:461997machine # [ 64.432334] dhcpcd[647]: vethc5645dd1: adding address fe80::1c63:16ff:fe24:fd461998machine # [ 64.513638] systemd[1]: Started libcontainer container afce97550946933590e817b3420e406d2924fd2175a44a1000c408299b80f549.1999machine # [ 64.630314] systemd[1]: Started libcontainer container 2341817c905e0c75dc98399ffc9440d28a40c8803cf99d484076bc35ea1759dd.2000machine # [ 64.699179] systemd[1]: cri-containerd-2341817c905e0c75dc98399ffc9440d28a40c8803cf99d484076bc35ea1759dd.scope: Deactivated successfully.2001machine # [ 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.2002machine # [ 65.347834] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-2341817c905e0c75dc98399ffc9440d28a40c8803cf99d484076bc35ea1759dd-rootfs.mount: Deactivated successfully.2003machine # [ 65.367643] dhcpcd[647]: vethc5645dd1: soliciting a DHCP lease2004machine # [ 66.019356] dhcpcd[647]: vethc5645dd1: soliciting an IPv6 router2005machine # [ 66.207088] systemd[1]: cri-containerd-afce97550946933590e817b3420e406d2924fd2175a44a1000c408299b80f549.scope: Deactivated successfully.2006machine # [ 66.265299] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-afce97550946933590e817b3420e406d2924fd2175a44a1000c408299b80f549-rootfs.mount: Deactivated successfully.2007machine # [ 66.302354] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-afce97550946933590e817b3420e406d2924fd2175a44a1000c408299b80f549-shm.mount: Deactivated successfully.2008machine # [ 66.515608] cni0: port 1(vethc5645dd1) entered disabled state2009machine # [ 66.364745] dhcpcd[647]: vethc5645dd1: carrier lost2010machine # [ 66.517501] vethc5645dd1 (unregistering): left allmulticast mode2011machine # [ 66.518559] vethc5645dd1 (unregistering): left promiscuous mode2012machine # [ 66.519690] cni0: port 1(vethc5645dd1) entered disabled state2013machine # [ 66.388110] systemd[1]: run-netns-cni\x2d64cac022\x2dae18\x2dfed4\x2dac8a\x2d5cb0d43e5db2.mount: Deactivated successfully.2014machine # [ 66.437395] dhcpcd[647]: vethc5645dd1: deleting address fe80::1c63:16ff:fe24:fd462015machine # NAME: niks32016machine # LAST DEPLOYED: Sun Sep 13 15:16:59 20262017machine # NAMESPACE: niks32018machine # STATUS: deployed2019machine # REVISION: 12020machine # DESCRIPTION: Install complete2021machine # TEST SUITE: niks3-test2022machine # Last Started: Sun Sep 13 15:17:16 20262023machine # Last Completed: Sun Sep 13 15:17:18 20262024machine # Phase: Succeeded2025machine: (finished: must succeed: helm test -n niks3 niks3 --timeout 2m >&2, in 3.20 seconds)2026(finished: subtest: helm test hook passes, in 3.20 seconds)2027(finished: run the VM test script, in 67.33 seconds)2028test script finished in 67.38s2029cleanup2030kill QemuMachine (pid 45)2031machine # qemu-system-x86_64: terminating on signal 15 from pid 39 (/nix/store/b5bpi6zfajzzrwwpgba2q6li3nnya4bs-python3-3.14.7/bin/python3.14)2032(finished: cleanup, in 0.72 seconds)2033additionally exposed symbols:2034 machine,2035 vlan1,2036 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_ssh2037time=2026-09-13T15:17:07.552Z level=INFO msg="Uploading 8 paths to localhost (0 already cached)"2038time=2026-09-13T15:17:07.555Z level=INFO msg="Uploading h6q94p1jw42irzqybm1049fmxakh8701-mailcap-2.1.54 (116.6KB)"2039time=2026-09-13T15:17:07.555Z level=INFO msg="Uploading n51dhmdbik1kfrsm62j5knavmigwrl1a-glibc-2.42-84 (33.4MB)"2040time=2026-09-13T15:17:07.556Z level=INFO msg="Uploading 69rx9yid472ww68bbf95nndvq8zi96ws-niks3-1.11.0 (7.7MB)"2041time=2026-09-13T15:17:07.556Z level=INFO msg="Uploading ssvq1r0xd8f7paf6zqgpfql1a4drwhy2-xgcc-15.3.0-libgcc (193.0KB)"2042time=2026-09-13T15:17:07.557Z level=INFO msg="Uploading yh8rykx8wakl1ccn8rc351f6r2wbg4cn-libunistring-1.4.2 (2.0MB)"2043time=2026-09-13T15:17:07.557Z level=INFO msg="Uploading p0ff33dca0fbkskqwrl3spvxcn5974h0-tzdata-2026c (2.0MB)"2044time=2026-09-13T15:17:07.557Z level=INFO msg="Uploading nb6fq3nrjmyx9f9syrfnmsyfhx1ks9vg-iana-etc-20251215 (557.8KB)"2045time=2026-09-13T15:17:07.560Z level=INFO msg="Uploading nga9d6m9iplygw3iqghk2g840nz7b0gy-libidn2-2.3.8 (359.5KB)"2046time=2026-09-13T15:17:09.113Z level=INFO msg="Uploading 8 narinfos"2047time=2026-09-13T15:17:09.161Z level=INFO msg="Upload complete. (1.811s)"2048