Machine state will be reset. To keep it, pass --keep-vm-state start all VLans start vlan running vlan (pid 5; ctl /build/vde1.ctl) (finished: start all VLans, in 0.00 seconds) Test will time out and terminate in 3600 seconds run the VM test script additionally exposed symbols: machine, vlan1, start_all, test_script, machines, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, Machine start all VMs machine: starting vm mke2fs 1.47.0 (5-Feb-2023) machine # Disk image do not exist, creating the virtualisation disk image... machine # Formatting '/build/vm-state-machine/tmp.W9OKe9EXW6', fmt=raw size=4294967296 machine # Discarding device blocks: 0/1048576 done machine # Creating filesystem with 1048576 4k blocks and 262144 inodes machine # Filesystem UUID: 286efa5a-ee94-441a-af6a-be11226be38d machine # Superblock backups stored on blocks: machine # 32768, 98304, 163840, 229376, 294912, 819200, 884736 machine # machine # Allocating group tables: 0/32 done machine # Writing inode tables: 0/32 done machine # Creating journal (16384 blocks): done machine # Writing superblocks and filesystem accounting information: 0/32 done machine # machine # Virtualisation disk image created. machine: QEMU running (pid 7) (finished: start all VMs, in 0.16 seconds) machine: waiting for unit k3s machine: waiting for the VM to finish booting machine # cSeaBIOS (version rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org) machine # machine # machine # iPXE (http://ipxe.org) 00:03.0 CA00 PCI2.10 PnP PMM+5EFD0AF0+5EF30AF0 CA00 machine # Press Ctrl-B to configure iPXE (PCI 00:03.0)... machine # machine # machine # machine # machine # iPXE (http://ipxe.org) 00:09.0 CB00 PCI2.10 PnP PMM 5EFD0AF0 5EF30AF0 CB00 machine # Press Ctrl-B to configure iPXE (PCI 00:09.0)... machine # machine # machine # Booting from ROM... machine # Probing EDD (edd=off to disable)... oc[ 0.000000] Linux version 6.6.30 (nixbld@localhost) (gcc (GCC) 13.2.0, GNU ld (GNU Binutils) 2.41) #1-NixOS SMP PREEMPT_DYNAMIC Thu May 2 14:32:50 UTC 2024 machine # [ 0.000000] Command line: console=ttyS0 panic=1 boot.panic_on_fail clocksource=acpi_pm loglevel=7 net.ifnames=0 init=/nix/store/afx4179n3lh9n1kbxsz5wv5alfhqc1m0-nixos-system-machine-test/init regInfo=/nix/store/8ghsyiy30k6j8hlzj47h5k448dl0wr68-closure-info/registration console=ttyS0 machine # [ 0.000000] BIOS-provided physical RAM map: machine # [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable machine # [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000005ffdafff] usable machine # [ 0.000000] BIOS-e820: [mem 0x000000005ffdb000-0x000000005fffffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved machine # [ 0.000000] BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved machine # [ 0.000000] NX (Execute Disable) protection: active machine # [ 0.000000] APIC: Static calls initialized machine # [ 0.000000] SMBIOS 3.0.0 present. machine # [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014 machine # [ 0.000000] Hypervisor detected: KVM machine # [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 machine # [ 0.000000] kvm-clock: using sched offset of 376785657 cycles machine # [ 0.000002] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns machine # [ 0.000004] tsc: Detected 2794.748 MHz processor machine # [ 0.001170] last_pfn = 0x5ffdb max_arch_pfn = 0x400000000 machine # [ 0.001208] MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs machine # [ 0.001211] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT machine # [ 0.003889] found SMP MP-table at [mem 0x000f5430-0x000f543f] machine # [ 0.003906] Using GB pages for direct mapping machine # [ 0.004090] RAMDISK: [mem 0x5f483000-0x5ffcffff] machine # [ 0.004095] ACPI: Early table checksum verification disabled machine # [ 0.004097] ACPI: RSDP 0x00000000000F5250 000014 (v00 BOCHS ) machine # [ 0.004101] ACPI: RSDT 0x000000005FFE1CE4 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.004106] ACPI: FACP 0x000000005FFE1B98 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.004110] ACPI: DSDT 0x000000005FFE0040 001B58 (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.004113] ACPI: FACS 0x000000005FFE0000 000040 machine # [ 0.004115] ACPI: APIC 0x000000005FFE1C0C 000078 (v03 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.004118] ACPI: HPET 0x000000005FFE1C84 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.004120] ACPI: WAET 0x000000005FFE1CBC 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) machine # [ 0.004122] ACPI: Reserving FACP table memory at [mem 0x5ffe1b98-0x5ffe1c0b] machine # [ 0.004124] ACPI: Reserving DSDT table memory at [mem 0x5ffe0040-0x5ffe1b97] machine # [ 0.004124] ACPI: Reserving FACS table memory at [mem 0x5ffe0000-0x5ffe003f] machine # [ 0.004125] ACPI: Reserving APIC table memory at [mem 0x5ffe1c0c-0x5ffe1c83] machine # [ 0.004126] ACPI: Reserving HPET table memory at [mem 0x5ffe1c84-0x5ffe1cbb] machine # [ 0.004127] ACPI: Reserving WAET table memory at [mem 0x5ffe1cbc-0x5ffe1ce3] machine # [ 0.004376] No NUMA configuration found machine # [ 0.004377] Faking a node at [mem 0x0000000000000000-0x000000005ffdafff] machine # [ 0.004379] NODE_DATA(0) allocated [mem 0x5ffd5000-0x5ffdafff] machine # [ 0.004397] Zone ranges: machine # [ 0.004397] DMA [mem 0x0000000000001000-0x0000000000ffffff] machine # [ 0.004399] DMA32 [mem 0x0000000001000000-0x000000005ffdafff] machine # [ 0.004401] Normal empty machine # [ 0.004401] Device empty machine # [ 0.004402] Movable zone start for each node machine # [ 0.004403] Early memory node ranges machine # [ 0.004404] node 0: [mem 0x0000000000001000-0x000000000009efff] machine # [ 0.004405] node 0: [mem 0x0000000000100000-0x000000005ffdafff] machine # [ 0.004406] Initmem setup node 0 [mem 0x0000000000001000-0x000000005ffdafff] machine # [ 0.004613] On node 0, zone DMA: 1 pages in unavailable ranges machine # [ 0.004629] On node 0, zone DMA: 97 pages in unavailable ranges machine # [ 0.008030] On node 0, zone DMA32: 37 pages in unavailable ranges machine # [ 0.008537] ACPI: PM-Timer IO Port: 0x608 machine # [ 0.008547] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) machine # [ 0.008579] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 machine # [ 0.008582] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) machine # [ 0.008584] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) machine # [ 0.008585] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) machine # [ 0.008586] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) machine # [ 0.008587] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) machine # [ 0.008590] ACPI: Using ACPI (MADT) for SMP configuration information machine # [ 0.008591] ACPI: HPET id: 0x8086a201 base: 0xfed00000 machine # [ 0.008595] TSC deadline timer available machine # [ 0.008596] smpboot: Allowing 1 CPUs, 0 hotplug CPUs machine # [ 0.008616] kvm-guest: APIC: eoi() replaced with kvm_guest_apic_eoi_write() machine # [ 0.008643] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff] machine # [ 0.008645] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff] machine # [ 0.008646] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff] machine # [ 0.008647] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff] machine # [ 0.008649] [mem 0x60000000-0xfeffbfff] available for PCI devices machine # [ 0.008650] Booting paravirtualized kernel on KVM machine # [ 0.008652] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns machine # [ 0.013440] setup_percpu: NR_CPUS:384 nr_cpumask_bits:1 nr_cpu_ids:1 nr_node_ids:1 machine # [ 0.013743] percpu: Embedded 84 pages/cpu s221184 r8192 d114688 u2097152 machine # [ 0.013780] kvm-guest: PV spinlocks disabled, single CPU machine # [ 0.013782] Kernel command line: console=ttyS0 panic=1 boot.panic_on_fail clocksource=acpi_pm loglevel=7 net.ifnames=0 init=/nix/store/afx4179n3lh9n1kbxsz5wv5alfhqc1m0-nixos-system-machine-test/init regInfo=/nix/store/8ghsyiy30k6j8hlzj47h5k448dl0wr68-closure-info/registration console=ttyS0 machine # [ 0.013890] Unknown kernel command line parameters "regInfo=/nix/store/8ghsyiy30k6j8hlzj47h5k448dl0wr68-closure-info/registration", will be passed to user space. machine # [ 0.013913] random: crng init done machine # [ 0.014197] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes, linear) machine # [ 0.014242] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear) machine # [ 0.014266] Fallback order for Node 0: 0 machine # [ 0.014268] Built 1 zonelists, mobility grouping on. Total pages: 386779 machine # [ 0.014269] Policy zone: DMA32 machine # [ 0.014575] mem auto-init: stack:all(zero), heap alloc:off, heap free:off machine # [ 0.016937] Memory: 1488428K/1572324K available (14336K kernel code, 2363K rwdata, 10896K rodata, 3088K init, 4568K bss, 83636K reserved, 0K cma-reserved) machine # [ 0.017790] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 machine # [ 0.017813] ftrace: allocating 42708 entries in 167 pages machine # [ 0.025156] ftrace: allocated 167 pages with 5 groups machine # [ 0.025781] Dynamic Preempt: voluntary machine # [ 0.026031] rcu: Preemptible hierarchical RCU implementation. machine # [ 0.026032] rcu: RCU event tracing is enabled. machine # [ 0.026032] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=1. machine # [ 0.026033] Trampoline variant of Tasks RCU enabled. machine # [ 0.026034] Rude variant of Tasks RCU enabled. machine # [ 0.026034] Tracing variant of Tasks RCU enabled. machine # [ 0.026035] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. machine # [ 0.026035] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1 machine # [ 0.028939] NR_IRQS: 24832, nr_irqs: 256, preallocated irqs: 16 machine # [ 0.029163] rcu: srcu_init: Setting srcu_struct sizes based on contention. machine # [ 0.029259] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____) machine # [ 0.033723] Console: colour VGA+ 80x25 machine # [ 0.033763] printk: console [ttyS0] enabled machine # [ 0.178224] ACPI: Core revision 20230628 machine # [ 0.178955] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns machine # [ 0.181326] APIC: Switch to symmetric I/O mode setup machine # [ 0.182807] x2apic enabled machine # [ 0.183727] APIC: Switched APIC routing to: physical x2apic machine # [ 0.185880] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 machine # [ 0.187148] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x2848df6a9de, max_idle_ns: 440795280912 ns machine # [ 0.189777] Calibrating delay loop (skipped) preset value.. 5589.49 BogoMIPS (lpj=2794748) machine # [ 0.190871] x86/cpu: User Mode Instruction Prevention (UMIP) activated machine # [ 0.191886] Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127 machine # [ 0.192776] Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0 machine # [ 0.193781] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization machine # [ 0.194778] Spectre V2 : Mitigation: Retpolines machine # [ 0.195776] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch machine # [ 0.196776] Spectre V2 : Spectre v2 / SpectreRSB : Filling RSB on VMEXIT machine # [ 0.197782] Spectre V2 : Enabling Speculation Barrier for firmware calls machine # [ 0.198776] RETBleed: Mitigation: untrained return thunk machine # [ 0.199778] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier machine # [ 0.200777] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl machine # [ 0.201776] Speculative Return Stack Overflow: IBPB-extending microcode not applied! machine # [ 0.202776] Speculative Return Stack Overflow: WARNING: See https://kernel.org/doc/html/latest/admin-guide/hw-vuln/srso.html for mitigation options. machine # [ 0.202777] Speculative Return Stack Overflow: Vulnerable: Safe RET, no microcode machine # [ 0.204789] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' machine # [ 0.205776] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' machine # [ 0.206776] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' machine # [ 0.207776] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 machine # [ 0.208776] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'compacted' format. machine # [ 0.236319] Freeing SMP alternatives memory: 36K machine # [ 0.236777] pid_max: default: 32768 minimum: 301 machine # [ 0.237838] LSM: initializing lsm=capability,landlock,yama,selinux,bpf,integrity machine # [ 0.238807] landlock: Up and running. machine # [ 0.239776] Yama: becoming mindful. machine # [ 0.240780] SELinux: Initializing. machine # [ 0.241810] LSM support for eBPF active machine # [ 0.242812] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear) machine # [ 0.243779] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear) machine # [ 0.245172] smpboot: CPU0: AMD EPYC 7402P 24-Core Processor (family: 0x17, model: 0x31, stepping: 0x0) machine # [ 0.246001] RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1. machine # [ 0.246817] RCU Tasks Rude: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1. machine # [ 0.247807] RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1. machine # [ 0.248811] Performance Events: Fam17h+ core perfctr, AMD PMU driver. machine # [ 0.249780] ... version: 0 machine # [ 0.250743] ... bit width: 48 machine # [ 0.250779] ... generic registers: 6 machine # [ 0.251705] ... value mask: 0000ffffffffffff machine # [ 0.251779] ... max period: 00007fffffffffff machine # [ 0.252506] ... fixed-purpose events: 0 machine # [ 0.252779] ... event mask: 000000000000003f machine # [ 0.253905] signal: max sigframe size: 1776 machine # [ 0.254814] rcu: Hierarchical SRCU implementation. machine # [ 0.255779] rcu: Max phase no-delay instances is 400. machine # [ 0.260437] smp: Bringing up secondary CPUs ... machine # [ 0.260795] smp: Brought up 1 node, 1 CPU machine # [ 0.261364] smpboot: Max logical packages: 1 machine # [ 0.261780] smpboot: Total of 1 processors activated (5589.49 BogoMIPS) machine # [ 0.262995] devtmpfs: initialized machine # [ 0.263534] x86/mm: Memory block size: 128MB machine # [ 0.264645] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns machine # [ 0.264789] futex hash table entries: 256 (order: 2, 16384 bytes, linear) machine # [ 0.265843] pinctrl core: initialized pinctrl subsystem machine # [ 0.266972] PM: RTC time: 05:59:53, date: 2024-05-13 machine # [ 0.268438] NET: Registered PF_NETLINK/PF_ROUTE protocol family machine # [ 0.268987] DMA: preallocated 256 KiB GFP_KERNEL pool for atomic allocations machine # [ 0.269782] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations machine # [ 0.270782] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations machine # [ 0.271790] audit: initializing netlink subsys (disabled) machine # [ 0.272971] thermal_sys: Registered thermal governor 'bang_bang' machine # [ 0.272973] thermal_sys: Registered thermal governor 'step_wise' machine # [ 0.273783] audit: type=2000 audit(1715579994.041:1): state=initialized audit_enabled=0 res=1 machine # [ 0.275783] thermal_sys: Registered thermal governor 'user_space' machine # [ 0.275802] cpuidle: using governor menu machine # [ 0.277378] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 machine # [ 0.277927] PCI: Using configuration type 1 for base access machine # [ 0.278778] PCI: Using configuration type 1 for extended access machine # [ 0.280014] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. machine # [ 0.310846] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages machine # [ 0.311780] HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page machine # [ 0.312779] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages machine # [ 0.313778] HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page machine # [ 0.315230] ACPI: Added _OSI(Module Device) machine # [ 0.315779] ACPI: Added _OSI(Processor Device) machine # [ 0.316422] ACPI: Added _OSI(3.0 _SCP Extensions) machine # [ 0.316778] ACPI: Added _OSI(Processor Aggregator Device) machine # [ 0.318851] ACPI: 1 ACPI AML tables successfully acquired and loaded machine # [ 0.320839] ACPI: _OSC evaluation for CPUs failed, trying _PDC machine # [ 0.321822] ACPI: Interpreter enabled machine # [ 0.322387] ACPI: PM: (supports S0 S3 S4 S5) machine # [ 0.322778] ACPI: Using IOAPIC for interrupt routing machine # [ 0.323476] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug machine # [ 0.323778] PCI: Using E820 reservations for host bridge windows machine # [ 0.324921] ACPI: Enabled 2 GPEs in block 00 to 0F machine # [ 0.329608] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) machine # [ 0.329785] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3] machine # [ 0.331099] acpiphp: Slot [3] registered machine # [ 0.331682] acpiphp: Slot [4] registered machine # [ 0.331801] acpiphp: Slot [5] registered machine # [ 0.332444] acpiphp: Slot [6] registered machine # [ 0.332801] acpiphp: Slot [7] registered machine # [ 0.333379] acpiphp: Slot [8] registered machine # [ 0.333802] acpiphp: Slot [9] registered machine # [ 0.334364] acpiphp: Slot [10] registered machine # [ 0.334802] acpiphp: Slot [11] registered machine # [ 0.335378] acpiphp: Slot [12] registered machine # [ 0.335803] acpiphp: Slot [13] registered machine # [ 0.336464] acpiphp: Slot [14] registered machine # [ 0.336801] acpiphp: Slot [15] registered machine # [ 0.337390] acpiphp: Slot [16] registered machine # [ 0.337801] acpiphp: Slot [17] registered machine # [ 0.338412] acpiphp: Slot [18] registered machine # [ 0.338801] acpiphp: Slot [19] registered machine # [ 0.339405] acpiphp: Slot [20] registered machine # [ 0.339804] acpiphp: Slot [21] registered machine # [ 0.340356] acpiphp: Slot [22] registered machine # [ 0.340802] acpiphp: Slot [23] registered machine # [ 0.341413] acpiphp: Slot [24] registered machine # [ 0.341801] acpiphp: Slot [25] registered machine # [ 0.342381] acpiphp: Slot [26] registered machine # [ 0.342802] acpiphp: Slot [27] registered machine # [ 0.343371] acpiphp: Slot [28] registered machine # [ 0.343807] acpiphp: Slot [29] registered machine # [ 0.344406] acpiphp: Slot [30] registered machine # [ 0.344802] acpiphp: Slot [31] registered machine # [ 0.345374] PCI host bridge to bus 0000:00 machine # [ 0.345796] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] machine # [ 0.346768] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] machine # [ 0.346778] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] machine # [ 0.347778] pci_bus 0000:00: root bus resource [mem 0x60000000-0xfebfffff window] machine # [ 0.348779] pci_bus 0000:00: root bus resource [mem 0x100000000-0x17fffffff window] machine # [ 0.349779] pci_bus 0000:00: root bus resource [bus 00-ff] machine # [ 0.350719] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 machine # [ 0.351198] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 machine # [ 0.352323] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 machine # [ 0.356155] pci 0000:00:01.1: reg 0x20: [io 0xc1e0-0xc1ef] machine # [ 0.358239] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] machine # [ 0.358779] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] machine # [ 0.359661] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] machine # [ 0.359779] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] machine # [ 0.360988] pci 0000:00:01.2: [8086:7020] type 00 class 0x0c0300 machine # [ 0.364310] pci 0000:00:01.2: reg 0x20: [io 0xc100-0xc11f] machine # [ 0.367105] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 machine # [ 0.368173] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI machine # [ 0.368787] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB machine # [ 0.369991] pci 0000:00:02.0: [1234:1111] type 00 class 0x030000 machine # [ 0.371781] pci 0000:00:02.0: reg 0x10: [mem 0xfd000000-0xfdffffff pref] machine # [ 0.374781] pci 0000:00:02.0: reg 0x18: [mem 0xfebd0000-0xfebd0fff] machine # [ 0.379780] pci 0000:00:02.0: reg 0x30: [mem 0xfebc0000-0xfebcffff pref] machine # [ 0.380821] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff] machine # [ 0.382060] pci 0000:00:03.0: [1af4:1000] type 00 class 0x020000 machine # [ 0.384779] pci 0000:00:03.0: reg 0x10: [io 0xc120-0xc13f] machine # [ 0.386779] pci 0000:00:03.0: reg 0x14: [mem 0xfebd1000-0xfebd1fff] machine # [ 0.390779] pci 0000:00:03.0: reg 0x20: [mem 0xfe000000-0xfe003fff 64bit pref] machine # [ 0.393778] pci 0000:00:03.0: reg 0x30: [mem 0xfeb40000-0xfeb7ffff pref] machine # [ 0.396057] pci 0000:00:04.0: [1af4:1005] type 00 class 0x00ff00 machine # [ 0.397779] pci 0000:00:04.0: reg 0x10: [io 0xc140-0xc15f] machine # [ 0.399321] pci 0000:00:04.0: reg 0x14: [mem 0xfebd2000-0xfebd2fff] machine # [ 0.403779] pci 0000:00:04.0: reg 0x20: [mem 0xfe004000-0xfe007fff 64bit pref] machine # [ 0.407074] pci 0000:00:05.0: [1af4:1009] type 00 class 0x000200 machine # [ 0.408779] pci 0000:00:05.0: reg 0x10: [io 0xc080-0xc0bf] machine # [ 0.411451] pci 0000:00:05.0: reg 0x14: [mem 0xfebd3000-0xfebd3fff] machine # [ 0.414779] pci 0000:00:05.0: reg 0x20: [mem 0xfe008000-0xfe00bfff 64bit pref] machine # [ 0.418748] pci 0000:00:06.0: [1af4:1009] type 00 class 0x000200 machine # [ 0.419779] pci 0000:00:06.0: reg 0x10: [io 0xc160-0xc17f] machine # [ 0.421349] pci 0000:00:06.0: reg 0x14: [mem 0xfebd4000-0xfebd4fff] machine # [ 0.426778] pci 0000:00:06.0: reg 0x20: [mem 0xfe00c000-0xfe00ffff 64bit pref] machine # [ 0.430019] pci 0000:00:07.0: [1af4:1009] type 00 class 0x000200 machine # [ 0.431779] pci 0000:00:07.0: reg 0x10: [io 0xc180-0xc19f] machine # [ 0.433365] pci 0000:00:07.0: reg 0x14: [mem 0xfebd5000-0xfebd5fff] machine # [ 0.437394] pci 0000:00:07.0: reg 0x20: [mem 0xfe010000-0xfe013fff 64bit pref] machine # [ 0.440061] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 machine # [ 0.443514] pci 0000:00:08.0: reg 0x10: [io 0xc000-0xc07f] machine # [ 0.444779] pci 0000:00:08.0: reg 0x14: [mem 0xfebd6000-0xfebd6fff] machine # [ 0.448403] pci 0000:00:08.0: reg 0x20: [mem 0xfe014000-0xfe017fff 64bit pref] machine # [ 0.452934] pci 0000:00:09.0: [1af4:1000] type 00 class 0x020000 machine # [ 0.454778] pci 0000:00:09.0: reg 0x10: [io 0xc1a0-0xc1bf] machine # [ 0.456371] pci 0000:00:09.0: reg 0x14: [mem 0xfebd7000-0xfebd7fff] machine # [ 0.459779] pci 0000:00:09.0: reg 0x20: [mem 0xfe018000-0xfe01bfff 64bit pref] machine # [ 0.461779] pci 0000:00:09.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] machine # [ 0.464046] pci 0000:00:0a.0: [1af4:1052] type 00 class 0x090000 machine # [ 0.466174] pci 0000:00:0a.0: reg 0x14: [mem 0xfebd8000-0xfebd8fff] machine # [ 0.468778] pci 0000:00:0a.0: reg 0x20: [mem 0xfe01c000-0xfe01ffff 64bit pref] machine # [ 0.471944] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 machine # [ 0.474785] pci 0000:00:0b.0: reg 0x10: [io 0xc0c0-0xc0ff] machine # [ 0.476781] pci 0000:00:0b.0: reg 0x14: [mem 0xfebd9000-0xfebd9fff] machine # [ 0.480784] pci 0000:00:0b.0: reg 0x20: [mem 0xfe020000-0xfe023fff 64bit pref] machine # [ 0.484483] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 machine # [ 0.485782] pci 0000:00:0c.0: reg 0x10: [io 0xc1c0-0xc1df] machine # [ 0.487781] pci 0000:00:0c.0: reg 0x14: [mem 0xfebda000-0xfebdafff] machine # [ 0.491783] pci 0000:00:0c.0: reg 0x20: [mem 0xfe024000-0xfe027fff 64bit pref] machine # [ 0.496059] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 machine # [ 0.496960] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 machine # [ 0.497947] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 machine # [ 0.498946] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 machine # [ 0.499874] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 machine # [ 0.501287] iommu: Default domain type: Translated machine # [ 0.501780] iommu: DMA domain TLB invalidation policy: lazy mode machine # [ 0.502822] ACPI: bus type USB registered machine # [ 0.503518] usbcore: registered new interface driver usbfs machine # [ 0.503791] usbcore: registered new interface driver hub machine # [ 0.504631] usbcore: registered new device driver usb machine # [ 0.505539] NetLabel: Initializing machine # [ 0.505780] NetLabel: domain hash size = 128 machine # [ 0.506780] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO machine # [ 0.507829] NetLabel: unlabeled traffic allowed by default machine # [ 0.508783] PCI: Using ACPI for IRQ routing machine # [ 0.510156] pci 0000:00:02.0: vgaarb: setting as boot VGA device machine # [ 0.510774] pci 0000:00:02.0: vgaarb: bridge control possible machine # [ 0.510774] pci 0000:00:02.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none machine # [ 0.510784] vgaarb: loaded machine # [ 0.511613] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 machine # [ 0.511780] hpet0: 3 comparators, 64-bit 100.000000 MHz counter machine # [ 0.515842] clocksource: Switched to clocksource kvm-clock machine # [ 0.518638] VFS: Disk quotas dquot_6.6.0 machine # [ 0.519180] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) machine # [ 0.520883] pnp: PnP ACPI init machine # [ 0.522264] pnp: PnP ACPI: found 6 devices machine # [ 0.530185] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns machine # [ 0.532210] clocksource: Switched to clocksource acpi_pm machine # [ 0.533574] NET: Registered PF_INET protocol family machine # [ 0.534745] IP idents hash table entries: 32768 (order: 6, 262144 bytes, linear) machine # [ 0.537507] tcp_listen_portaddr_hash hash table entries: 1024 (order: 2, 16384 bytes, linear) machine # [ 0.540002] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear) machine # [ 0.541203] TCP established hash table entries: 16384 (order: 5, 131072 bytes, linear) machine # [ 0.543709] TCP bind hash table entries: 16384 (order: 7, 524288 bytes, linear) machine # [ 0.545873] TCP: Hash tables configured (established 16384 bind 16384) machine # [ 0.547549] MPTCP token hash table entries: 2048 (order: 3, 49152 bytes, linear) machine # [ 0.549163] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear) machine # [ 0.550592] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear) machine # [ 0.551984] NET: Registered PF_UNIX/PF_LOCAL protocol family machine # [ 0.553431] NET: Registered PF_XDP protocol family machine # [ 0.554661] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] machine # [ 0.556032] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] machine # [ 0.557422] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] machine # [ 0.558812] pci_bus 0000:00: resource 7 [mem 0x60000000-0xfebfffff window] machine # [ 0.560578] pci_bus 0000:00: resource 8 [mem 0x100000000-0x17fffffff window] machine # [ 0.562187] pci 0000:00:01.0: PIIX3: Enabling Passive Release machine # [ 0.563451] pci 0000:00:00.0: Limiting direct PCI/PCI transfers machine # [ 0.608136] ACPI: \_SB_.LNKD: Enabled at IRQ 11 machine # [ 0.653828] pci 0000:00:01.2: quirk_usb_early_handoff+0x0/0x7d0 took 87077 usecs machine # [ 0.656025] PCI: CLS 0 bytes, default 64 machine # [ 0.657148] Trying to unpack rootfs image as initramfs... machine # [ 0.661957] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2848df6a9de, max_idle_ns: 440795280912 ns machine # [ 0.669118] Initialise system trusted keyrings machine # [ 0.671774] workingset: timestamp_bits=40 max_order=19 bucket_order=0 machine # [ 0.675689] zbud: loaded machine # [ 0.700653] Key type asymmetric registered machine # [ 0.701476] Asymmetric key parser 'x509' registered machine # [ 0.703840] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251) machine # [ 0.707710] io scheduler mq-deadline registered machine # [ 0.708864] io scheduler kyber registered machine # [ 0.712160] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled machine # [ 0.716078] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A machine # [ 0.722770] Linux agpgart interface v0.103 machine # [ 0.724645] ACPI: bus type drm_connector registered machine # [ 0.727838] usbcore: registered new interface driver usbserial_generic machine # [ 0.731723] usbserial: USB Serial support registered for generic machine # [ 0.733158] amd_pstate: the _CPC object is not present in SBIOS or ACPI disabled machine # [ 0.735813] drop_monitor: Initializing network drop monitor service machine # [ 0.769965] NET: Registered PF_INET6 protocol family machine # [ 0.790527] Freeing initrd memory: 11572K machine # [ 0.792072] Segment Routing with IPv6 machine # [ 0.793023] In-situ OAM (IOAM) with IPv6 machine # [ 0.794315] IPI shorthand broadcast: enabled machine # [ 0.798517] sched_clock: Marking stable (642016397, 155605973)->(934063282, -136440912) machine # [ 0.800029] registered taskstats version 1 machine # [ 0.800790] Loading compiled-in X.509 certificates machine # [ 0.809275] Key type .fscrypt registered machine # [ 0.810262] Key type fscrypt-provisioning registered machine # [ 0.811599] PM: Magic number: 8:939:971 machine # [ 0.818978] RAS: Correctable Errors collector initialized. machine # [ 0.820444] clk: Disabling unused clocks machine # [ 0.823227] Freeing unused decrypted memory: 2028K machine # [ 0.824829] Freeing unused kernel image (initmem) memory: 3088K machine # [ 0.826088] Write protecting the kernel read-only data: 26624k machine # [ 0.827765] Freeing unused kernel image (rodata/data gap) memory: 1392K machine # [ 0.903728] x86/mm: Checked W+X mappings: passed, no W+X pages found. machine # [ 0.905232] Run /init as init process machine # machine # <<< NixOS Stage 1 >>> machine # machine # loading module virtio_balloon... machine # loading module virtio_console... machine # loading module virtio_rng... machine # loading module dm_mod... machine # [ 0.979181] device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com machine # running udev... machine # Starting systemd-udevd version 255.4 machine # [ 1.070664] rtc_cmos 00:05: RTC can wake from S4 machine # [ 1.076768] rtc_cmos 00:05: registered as rtc0 machine # [ 1.083696] rtc_cmos 00:05: setting system clock to 2024-05-13T05:59:54 UTC (1715579994) machine # [ 1.086052] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 machine # [ 1.098723] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs machine # [ 1.101341] serio: i8042 KBD port at 0x60,0x64 irq 1 machine # [ 1.110774] serio: i8042 AUX port at 0x60,0x64 irq 12 machine # [ 1.158654] SCSI subsystem initialized machine # [ 1.251723] ACPI: \_SB_.LNKC: Enabled at IRQ 10 machine # [ 1.253449] uhci_hcd 0000:00:01.2: UHCI Host Controller machine # [ 1.256991] scsi host0: ata_piix machine # [ 1.258259] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1 machine # [ 1.259896] scsi host1: ata_piix machine # [ 1.261746] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc1e0 irq 14 machine # [ 1.263193] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc1e8 irq 15 machine # [ 1.265092] uhci_hcd 0000:00:01.2: detected 2 ports machine # [ 1.266358] uhci_hcd 0000:00:01.2: irq 11, io port 0x0000c100 machine # [ 1.270051] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.06 machine # [ 1.271613] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 machine # [ 1.272369] usb usb1: Product: UHCI Host Controller machine # [ 1.273653] usb usb1: Manufacturer: Linux 6.6.30 uhci_hcd machine # [ 1.274848] usb usb1: SerialNumber: 0000:00:01.2 machine # [ 1.279950] hub 1-0:1.0: USB hub found machine # [ 1.280980] hub 1-0:1.0: 2 ports detected machine # [ 1.359850] ACPI: \_SB_.LNKA: Enabled at IRQ 10 machine # [ 1.415479] ACPI: \_SB_.LNKB: Enabled at IRQ 11 machine # [ 1.417803] ata2: found unknown device (class 0) machine # [ 1.419701] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100 machine # [ 1.422068] scsi 1:0:0:0: CD-ROM QEMU QEMU DVD-ROM 2.5+ PQ: 0 ANSI: 5 machine # [ 1.507638] usb 1-1: new full-speed USB device number 2 using uhci_hcd machine # [ 1.518642] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0 machine # [ 1.553925] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray machine # [ 1.555763] cdrom: Uniform CD-ROM driver Revision: 3.20 machine # [ 1.679536] usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 machine # [ 1.681728] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=10 machine # [ 1.683570] usb 1-1: Product: QEMU USB Tablet machine # [ 1.688352] usb 1-1: Manufacturer: QEMU machine # [ 1.689175] usb 1-1: SerialNumber: 28754-0000:00:01.2-1 machine # [ 1.751735] hid: raw HID events driver (C) Jiri Kosina machine # [ 1.767684] usbcore: registered new interface driver usbhid machine # [ 1.769274] usbhid: USB HID core driver machine # [ 1.774647] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input2 machine # [ 1.777678] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:01.2-1/input0 machine # [ 1.931645] virtio_blk virtio5: 1/0/0 default/read/poll queues machine # [ 1.937575] virtio_blk virtio5: [vda] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) machine # [ 1.950800] 9pnet: Installing 9P2000 support machine # kbd_mode: KDSKBMODE: Inappropriate ioctl for device machine # %Gstarting device mapper and LVM... machine # checking /dev/disk/by-label/nixos... machine # fsck (busybox 1.36.1) machine # [fsck.ext4 (1) -- /mnt-root/] fsck.ext4 -a /dev/disk/by-label/nixos machine # nixos: clean, 11/262144 files, 36942/1048576 blocks machine # mounting /dev/disk/by-label/nixos on /... machine # [ 2.153166] EXT4-fs (vda): mounted filesystem 286efa5a-ee94-441a-af6a-be11226be38d r/w with ordered data mode. Quota mode: none. machine # [ 2.158637] EXT4-fs (vda): re-mounted 286efa5a-ee94-441a-af6a-be11226be38d r/w. Quota mode: none. machine # mounting nix-store on /nix/.ro-store... machine # [ 2.190340] FS-Cache: Loaded machine # [ 2.198381] 9p: Installing v9fs 9p2000 file system support machine # mounting tmpfs on /nix/.rw-store... machine # mounting shared on /tmp/shared... machine # mounting xchg on /tmp/xchg... machine # mounting overlay filesystem on /nix/store... machine # machine # <<< NixOS Stage 2 >>> machine # machine # [ 2.457617] EXT4-fs (vda): re-mounted 286efa5a-ee94-441a-af6a-be11226be38d r/w. Quota mode: none. machine # [ 2.460163] booting system configuration /nix/store/afx4179n3lh9n1kbxsz5wv5alfhqc1m0-nixos-system-machine-test machine # running activation script... machine # setting up /etc... machine # starting systemd... machine # [ 4.173021] systemd[1]: Inserted module 'autofs4' machine # [ 4.248754] systemd[1]: systemd 255.4 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON +UTMP -SYSVINIT default-hierarchy=unified) machine # [ 4.253383] systemd[1]: Detected virtualization kvm. machine # [ 4.254150] systemd[1]: Detected architecture x86-64. machine # [ 4.260299] systemd[1]: Hostname set to . machine # [ 4.261500] systemd[1]: Initializing machine ID from random generator. machine # [ 4.296362] systemd[1]: memfd_create() called without MFD_EXEC or MFD_NOEXEC_SEAL set machine # [ 4.631803] systemd[1]: bpf-lsm: LSM BPF program attached machine # [ 5.451722] systemd[1]: Queued start job for default target Multi-User System. machine # [ 5.484050] systemd[1]: Created slice Slice /system/getty. machine # [ 5.485696] systemd[1]: Created slice Slice /system/modprobe. machine # [ 5.487164] systemd[1]: Created slice User and Session Slice. machine # [ 5.488005] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. machine # [ 5.489130] systemd[1]: Started Forward Password Requests to Wall Directory Watch. machine # [ 5.490290] systemd[1]: Expecting device /dev/hvc0... machine # [ 5.490896] systemd[1]: Expecting device /dev/ttyS0... machine # [ 5.491606] systemd[1]: Expecting device /sys/subsystem/net/devices/eth1... machine # [ 5.492389] systemd[1]: Reached target Local Encrypted Volumes. machine # [ 5.493054] systemd[1]: Reached target Containers. machine # [ 5.493672] systemd[1]: Reached target Path Units. machine # [ 5.494201] systemd[1]: Reached target Remote File Systems. machine # [ 5.494880] systemd[1]: Reached target Slice Units. machine # [ 5.495498] systemd[1]: Reached target Swaps. machine # [ 5.503746] systemd[1]: Listening on Process Core Dump Socket. machine # [ 5.506606] systemd[1]: Listening on Journal Socket (/dev/log). machine # [ 5.508480] systemd[1]: Listening on Journal Socket. machine # [ 5.512211] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket. machine # [ 5.516339] systemd[1]: Listening on udev Control Socket. machine # [ 5.518707] systemd[1]: Listening on udev Kernel Socket. machine # [ 5.532890] systemd[1]: Mounting Huge Pages File System... machine # [ 5.544955] systemd[1]: Mounting POSIX Message Queue File System... machine # [ 5.555492] systemd[1]: Mounting Kernel Debug File System... machine # [ 5.573929] systemd[1]: Starting Create List of Static Device Nodes... machine # [ 5.589585] systemd[1]: Starting Load Kernel Module configfs... machine # [ 5.619742] systemd[1]: Starting Load Kernel Module drm... machine # [ 5.640612] systemd[1]: Starting Load Kernel Module efi_pstore... machine # [ 5.653931] systemd[1]: Starting Load Kernel Module fuse... machine # [ 5.671776] systemd[1]: Starting mount-pstore.service... machine # [ 5.690790] systemd[1]: Starting Create SUID/SGID Wrappers... machine # [ 5.695916] systemd[1]: File System Check on Root Device was skipped because of an unmet condition check (ConditionPathIsReadWrite=!/). machine # [ 5.712980] systemd[1]: Starting Journal Service... machine # [ 5.725163] systemd[1]: Starting Load Kernel Modules... machine # [ 5.741931] systemd[1]: Starting Remount Root and Kernel File Systems... machine # [ 5.754789] systemd[1]: Starting Coldplug All udev Devices... machine # [ 5.765077] systemd[1]: Mounted Huge Pages File System. machine # [ 5.768288] systemd[1]: Mounted POSIX Message Queue File System. machine # [ 5.771818] systemd[1]: Mounted Kernel Debug File System. machine # [ 5.777718] systemd[1]: Finished Create List of Static Device Nodes. machine # [ 5.792044] systemd[1]: Starting Create Static Device Nodes in /dev gracefully... machine # [ 6.004108] EXT4-fs (vda): re-mounted 286efa5a-ee94-441a-af6a-be11226be38d r/w. Quota mode: none. machine # [ 6.029939] systemd[1]: Finished Remount Root and Kernel File Systems. machine # [ 6.040967] systemd[1]: Starting Load/Save OS Random Seed... machine # [ 6.046311] systemd-journald[372]: Collecting audit messages is disabled. machine # [ 6.086206] systemd[1]: modprobe@configfs.service: Deactivated successfully. machine # [ 6.090907] systemd[1]: Finished Load Kernel Module configfs. machine # [ 6.102554] systemd[1]: Mounting Kernel Configuration File System... machine # [ 6.105651] systemd[1]: modprobe@drm.service: Deactivated successfully. machine # [ 6.110032] systemd[1]: Finished Load Kernel Module drm. machine # [ 6.145218] systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. machine # [ 6.148111] systemd[1]: Finished Load Kernel Module efi_pstore. machine # [ 6.171951] systemd[1]: Mounted Kernel Configuration File System. machine # [ 6.216773] fuse: init (API version 7.39) machine # [ 6.239619] systemd[1]: modprobe@fuse.service: Deactivated successfully. machine # [ 6.243960] systemd[1]: Finished Load Kernel Module fuse. machine # [ 6.249065] systemd[1]: Finished Create Static Device Nodes in /dev gracefully. machine # [ 6.256815] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this. machine # [ 6.259644] systemd[1]: Mounting FUSE Control File System... machine # [ 6.267133] systemd[1]: Starting Create Static Device Nodes in /dev... machine # [ 6.271450] systemd[1]: Finished Load/Save OS Random Seed. machine # [ 6.317326] systemd[1]: Mounted FUSE Control File System. machine # [ 6.376068] tun: Universal TUN/TAP device driver, 1.6 machine # [ 6.398334] loop: module loaded machine # [ 6.416964] systemd[1]: Finished Load Kernel Modules. machine # [ 6.425957] systemd[1]: Starting Firewall... machine # [ 6.433894] systemd[1]: Starting Apply Kernel Variables... machine # [ 6.466804] systemd[1]: Started Journal Service. machine # [ 6.312565] systemd-modules-load[373]: Inserted module 'bridge' machine # [ 6.327627] systemd-modules-load[373]: Inserted module 'macvlan' machine # [ 6.346417] systemd-modules-load[373]: Inserted module 'tap' machine # [ 6.349975] systemd-modules-load[373]: Inserted module 'tun' machine # [ 6.355131] systemd-modules-load[373]: Inserted module 'loop' machine # [ 6.359833] systemd[1]: Starting Flush Journal to Persistent Storage... machine # [ 6.368888] systemd[1]: Finished Create Static Device Nodes in /dev. machine # [ 6.377925] systemd[1]: Reached target Preparation for Local File Systems. machine # [ 6.381774] systemd[1]: Reached target Local File Systems. machine # [ 6.387660] systemd[1]: Update Boot Loader Random Seed was skipped because no trigger condition checks were met. machine # [ 6.393445] systemd[1]: Starting Rule-based Manager for Device Events and Files... machine # [ 6.622354] systemd-journald[372]: Received client request to flush runtime journal. machine # [ 6.633944] systemd[1]: Finished Apply Kernel Variables. machine # [ 6.649883] systemd-udevd[415]: Using default interface naming scheme 'v255'. machine # [ 6.668097] systemd[1]: Finished Coldplug All udev Devices. machine # [ 6.675684] systemd[1]: Finished Flush Journal to Persistent Storage. machine # [ 6.676950] systemd[1]: Starting Create Volatile Files and Directories... machine # [ 6.802645] systemd[1]: Started Rule-based Manager for Device Events and Files. machine # [ 6.870578] systemd[1]: Finished Create Volatile Files and Directories. machine # [ 6.883291] systemd[1]: Starting Rebuild Journal Catalog... machine # [ 6.887964] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer... machine # [ 6.899325] systemd[1]: Starting Record System Boot/Shutdown in UTMP... machine # [ 7.129265] systemd[1]: Finished Record System Boot/Shutdown in UTMP. machine # [ 7.191928] systemd[1]: Finished Rebuild Journal Catalog. machine # [ 7.196704] systemd[1]: Starting Update is Completed... machine # [ 7.283645] systemd-oomd[501]: No swap; memory pressure usage will be degraded machine # [ 7.288899] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer. machine # [ 7.318082] systemd[1]: Finished Update is Completed. machine # [ 7.323727] systemd[1]: Found device /dev/hvc0. machine # [ 7.337923] systemd[1]: Found device /dev/ttyS0. machine # [ 7.343957] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully. machine # [ 7.349832] systemd[1]: Finished Create SUID/SGID Wrappers. machine # [ 7.440296] (udev-worker)[540]: Network interface NamePolicy= disabled on kernel command line. machine # [ 7.449336] (udev-worker)[513]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name. machine # [ 7.454109] (udev-worker)[513]: Network interface NamePolicy= disabled on kernel command line. machine # [ 7.618165] systemd[1]: Found device Virtio network device. machine # [ 7.795929] mousedev: PS/2 mouse device common for all mice machine # [ 7.838289] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3 machine # [ 7.853341] ACPI: button: Power Button [PWRF] machine # [ 7.931139] parport_pc 00:03: reported by Plug and Play ACPI machine # [ 7.936367] Floppy drive(s): fd0 is 2.88M AMI BIOS machine # [ 7.942082] parport0: PC-style at 0x378, irq 7 [PCSPP(,...)] machine # [ 7.960660] FDC 0 is a S82078B machine # [ 7.979264] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 machine # [ 8.020058] input: QEMU Virtio Keyboard as /devices/pci0000:00/0000:00:0a.0/virtio7/input/input4 machine # [ 8.052298] cryptd: max_cpu_qlen set to 1000 machine # [ 8.133306] bochs-drm 0000:00:02.0: vgaarb: deactivate vga console machine # [ 8.160044] AVX2 version of gcm_enc/dec engaged. machine # [ 8.183959] AES CTR mode by8 optimization enabled machine # [ 8.191373] Console: switching to colour dummy device 80x25 machine # [ 8.213076] [drm] Found bochs VGA, ID 0xb0c5. machine # [ 8.213638] [drm] Framebuffer size 16384 kB @ 0xfd000000, mmio @ 0xfebd0000. machine # [ 8.072591] systemd[1]: Starting Virtual Console Setup...[ 8.230120] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input6 machine # [ 8.231505] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input5 machine # machine # [ 8.233442] ppdev: user-space parallel port driver machine # [ 8.248057] [drm] Found EDID data blob. machine # [ 8.267163] [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:02.0 on minor 0 machine # [ 8.147042] 0f6yha712cnq8w4qz8hrym9fqp6wijcb-mount-pstore.sh[378]: Persistent Storage backend was not registered in time. machine # [ 8.150937] systemd[1]: Finished mount-pstore.service. machine # [ 8.154663] systemd[1]: Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). machine # [ 8.348971] fbcon: bochs-drmdrmfb (fb0) is primary device machine # [ 8.434607] Console: switching to colour frame buffer device 160x50 machine # [ 8.743092] bochs-drm 0000:00:02.0: [drm] fb0: bochs-drmdrmfb frame buffer device machine # [ 8.647640] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 8.651669] systemd[1]: Stopped Virtual Console Setup. machine # [ 8.660535] systemd[1]: Starting Virtual Console Setup... machine # [ 8.715681] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. machine # [ 8.719440] systemd[1]: Stopped Virtual Console Setup. machine # [ 8.728532] systemd[1]: Starting Virtual Console Setup... machine # [ 8.947951] systemd[1]: Finished Firewall. machine # [ 9.125023] kvm_amd: TSC scaling supported machine # [ 9.125580] kvm_amd: Nested Virtualization enabled machine # [ 9.126165] kvm_amd: Nested Paging enabled machine # [ 9.127006] kvm_amd: Virtual VMLOAD VMSAVE supported machine # [ 9.128112] kvm_amd: Virtual GIF supported machine # [ 9.128601] kvm_amd: LBR virtualization supported machine # [ 9.155745] EDAC MC: Ver: 3.0.0 machine # [ 9.545898] systemd[1]: Finished Virtual Console Setup. machine # [ 9.547185] systemd[1]: Reached target System Initialization. machine # [ 9.548202] systemd[1]: Started Daily Cleanup of Temporary Directories. machine # [ 9.549333] systemd[1]: Reached target Timer Units. machine # [ 9.551445] systemd[1]: Listening on D-Bus System Message Bus Socket. machine # [ 9.553749] systemd[1]: Listening on Nix Daemon Socket. machine # [ 9.555374] systemd[1]: Reached target Socket Units. machine # [ 9.556278] systemd[1]: Reached target Basic System. machine # [ 9.570063] systemd[1]: Starting Kernel Auditing... machine # [ 9.573401] systemd[1]: Started backdoor.service. machine # [ 9.580596] systemd[1]: Starting DHCP Client... machine # [ 9.588263] systemd[1]: Starting Name Service Cache Daemon (nsncd)... machine # [ 9.596404] systemd[1]: Started Reset console on configuration changes. machine # [ 9.611100] systemd[1]: Starting resolvconf update... machine # [ 9.618230] systemd[1]: Starting D-Bus System Message Bus... machine # connecting to host... machine # [ 9.739536] qx6q3lfs75iw3z8qi27vpfcmjcgyfbww-audit-disable[659]: No rules machine # [ 9.740941] dhcpcd[654]: dhcpcd-10.0.6 starting machine # [ 9.772810] systemd[1]: Finished Kernel Auditing. machine # [ 9.796355] dhcpcd[668]: dev: loaded udev machine: Guest shell says: b'Spawning backdoor root shell...\n' machine # [ 9.827268] systemd[1]: Started Name Service Cache Daemon (nsncd). machine: connected to guest root shell machine: (connecting took 10.48 seconds) (finished: waiting for the VM to finish booting, in 10.48 seconds) machine # [ 9.831249] systemd[1]: Reached target Host and Network Name Lookups. machine # [ 9.833461] nsncd[655]: May 13 06:00:02.978 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 3s }, path: "/var/run/nscd/socket" machine # [ 9.843828] systemd[1]: Reached target User and Group Name Lookups. machine # [ 10.023074] 8021q: 802.1Q VLAN Support v1.8 machine # [ 9.873572] systemd[1]: Starting User Login Management... machine # [ 10.020196] dbus-daemon[658]: dbus[658]: Unknown username "systemd-timesync" in message bus configuration file machine # [ 10.137467] systemd[1]: Started D-Bus System Message Bus. machine # [ 10.336739] cfg80211: Loading compiled-in X.509 certificates for regulatory database machine # [ 10.200752] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. machine # [ 10.240085] systemd[1]: Stopped target Host and Network Name Lookups. machine # [ 10.241787] systemd[1]: Stopping Host and Network Name Lookups... machine # [ 10.401021] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' machine # [ 10.401910] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' machine # [ 10.245187] systemd[1]: Stopped target User and Group Name Lookups. machine # [ 10.406764] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2 machine # [ 10.407800] cfg80211: failed to load regulatory.db machine # [ 10.256527] systemd[1]: Stopping User and Group Name Lookups... machine # [ 10.269932] systemd[1]: Stopping Name Service Cache Daemon (nsncd)... machine # [ 10.276743] systemd[1]: nscd.service: Deactivated successfully. machine # [ 10.279564] systemd[1]: Stopped Name Service Cache Daemon (nsncd). machine # [ 10.289563] systemd[1]: Starting Name Service Cache Daemon (nsncd)... machine # [ 10.314763] systemd-logind[687]: New seat seat0. machine # [ 10.323166] systemd-logind[687]: Watching system buttons on /dev/input/event2 (Power Button) machine # [ 10.325567] systemd-logind[687]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard) machine # [ 10.329175] systemd-logind[687]: Watching system buttons on /dev/input/event0 (AT Translated Set 2 keyboard) machine # [ 10.333772] systemd[1]: Started User Login Management. machine # [ 10.367523] systemd[1]: Finished resolvconf update. machine # [ 10.368814] systemd[1]: Reached target Preparation for Network. machine # [ 10.374817] systemd[1]: Starting Address configuration of eth1... machine # [ 10.400167] systemd[1]: Started Name Service Cache Daemon (nsncd). machine # [ 10.401830] nsncd[731]: May 13 06:00:03.551 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 3s }, path: "/var/run/nscd/socket" machine # [ 10.409167] systemd[1]: Reached target Host and Network Name Lookups. machine # [ 10.410478] systemd[1]: Reached target User and Group Name Lookups. machine # [ 10.601894] 8021q: adding VLAN 0 to HW filter on device eth0 machine # [ 10.448300] dhcpcd[668]: eth0: waiting for carrier machine # [ 10.450929] dhcpcd[668]: eth0: carrier acquired machine # [ 10.462154] dhcpcd[668]: DUID 00:01:00:01:2d:d4:68:e3:52:54:00:12:34:56 machine # [ 10.463935] dhcpcd[668]: eth0: IAID 00:12:34:56 machine # [ 10.465571] dhcpcd[668]: eth0: adding address fe80::5054:ff:fe12:3456 machine # [ 10.636954] 8021q: adding VLAN 0 to HW filter on device eth1 machine # [ 10.498224] network-addresses-eth1-start[747]: adding address 192.168.1.1/24... done machine # [ 10.516530] systemd[1]: Finished Address configuration of eth1. machine # [ 10.524821] systemd[1]: Starting Networking Setup... machine # [ 10.659095] systemd[1]: Finished Networking Setup. machine # [ 10.665531] systemd[1]: Starting Extra networking commands.... machine # [ 10.700064] systemd[1]: Finished Extra networking commands.. machine # [ 10.702637] systemd[1]: Reached target Network. machine # [ 10.708284] systemd[1]: Starting Permit User Sessions... machine # [ 10.743537] systemd[1]: Finished Permit User Sessions. machine # [ 10.750679] systemd[1]: Started Getty on tty1. machine # [ 10.753161] systemd[1]: Reached target Login Prompts. machine # [ 10.917360] dhcpcd[668]: eth0: soliciting an IPv6 router machine # [ 11.911380] dhcpcd[668]: eth0: soliciting a DHCP lease machine # [ 12.090565] NET: Registered PF_PACKET protocol family machine # [ 11.940992] dhcpcd[668]: eth0: offered 10.0.2.15 from 10.0.2.2 machine # [ 11.941985] dhcpcd[668]: eth0: leased 10.0.2.15 for 86400 seconds machine # [ 11.943409] dhcpcd[668]: eth0: adding route to 10.0.2.0/24 machine # [ 11.944688] dhcpcd[668]: eth0: adding default route via 10.0.2.2 machine # [ 12.041262] systemd[1]: Stopped target Host and Network Name Lookups. machine # [ 12.043696] systemd[1]: Stopping Host and Network Name Lookups... machine # [ 12.044839] systemd[1]: Stopped target User and Group Name Lookups. machine # [ 12.046740] systemd[1]: Stopping User and Group Name Lookups... machine # [ 12.048350] systemd[1]: Stopping Name Service Cache Daemon (nsncd)... machine # [ 12.056852] systemd[1]: nscd.service: Deactivated successfully. machine # [ 12.061076] systemd[1]: Stopped Name Service Cache Daemon (nsncd). machine # [ 12.077851] systemd[1]: Starting Name Service Cache Daemon (nsncd)... machine # [ 12.107749] dhcpcd[668]: eth0: Router Advertisement from fe80::2 machine # [ 12.109573] dhcpcd[668]: eth0: adding address fec0::5054:ff:fe12:3456/64 machine # [ 12.111634] dhcpcd[668]: eth0: adding route to fec0::/64 machine # [ 12.115147] systemd[1]: Started DHCP Client. machine # [ 12.116311] dhcpcd[668]: eth0: adding default route via fe80::2 machine # [ 12.122089] systemd[1]: Reached target Network is Online. machine # [ 12.129563] systemd[1]: Starting k3s service... machine # [ 12.146922] systemd[1]: Started Name Service Cache Daemon (nsncd). machine # [ 12.149224] systemd[1]: Reached target Host and Network Name Lookups. machine # [ 12.151380] systemd[1]: Reached target User and Group Name Lookups. machine # [ 12.155258] nsncd[870]: May 13 06:00:05.304 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 3s }, path: "/var/run/nscd/socket" machine # [ 12.251331] k3s[877]: time="2024-05-13T06:00:05Z" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock" machine # [ 12.254481] k3s[877]: time="2024-05-13T06:00:05Z" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/3e385e46fcffb163f336e2c55162854c8577cca4831e39e920cc7efcc160284c" machine # [ 16.478162] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="Starting k3s v1.29.4+k3s1 (94e29e2e)" machine # [ 16.483137] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="Configuring sqlite3 database connection pooling: maxIdleConns=2, maxOpenConns=0, connMaxLifetime=0s" machine # [ 16.485423] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="Configuring database table schema and indexes, this may take a moment..." machine # [ 16.491914] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="Database tables and indexes are up to date" machine # [ 16.498905] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="Kine available at unix://kine.sock" machine # [ 16.503076] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="generated self-signed CA certificate CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09.655990634 +0000 UTC notAfter=2034-05-11 06:00:09.655990634 +0000 UTC" machine # [ 16.509335] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.515252] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=system:k3s-supervisor,O=system:masters signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.519963] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.526075] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.529483] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=system:apiserver,O=system:masters signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.533853] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.539084] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.542846] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.546784] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="generated self-signed CA certificate CN=k3s-server-ca@1715580009: notBefore=2024-05-13 06:00:09.699851236 +0000 UTC notAfter=2034-05-11 06:00:09.699851236 +0000 UTC" machine # [ 16.552080] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.555103] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="generated self-signed CA certificate CN=k3s-request-header-ca@1715580009: notBefore=2024-05-13 06:00:09.705420659 +0000 UTC notAfter=2034-05-11 06:00:09.705420659 +0000 UTC" machine # [ 16.559355] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.563147] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="generated self-signed CA certificate CN=etcd-server-ca@1715580009: notBefore=2024-05-13 06:00:09.716294946 +0000 UTC notAfter=2034-05-11 06:00:09.716294946 +0000 UTC" machine # [ 16.567187] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.570718] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="generated self-signed CA certificate CN=etcd-peer-ca@1715580009: notBefore=2024-05-13 06:00:09.723944801 +0000 UTC notAfter=2034-05-11 06:00:09.723944801 +0000 UTC" machine # [ 16.575064] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 16.577896] k3s[877]: time="2024-05-13T06:00:09Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:09 +0000 UTC" machine # [ 17.074699] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="Saving cluster bootstrap data to datastore" machine # [ 17.078360] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:10 +0000 UTC" machine # [ 17.081059] k3s[877]: time="2024-05-13T06:00:10Z" level=warning msg="dynamiclistener [::]:6443: no cached certificate available for preload - deferring certificate load until storage initialization or first client request" machine # [ 17.083725] k3s[877]: time="2024-05-13T06:00:10Z" 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__1620_efe5_3e6d_8a9-103756:fec0::1620:efe5:3e6d:8a9 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=EC846238A342F5889C1143BD676C6A7AE04E445E]" machine # [ 17.362461] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=https://kubernetes.default.svc.cluster.local,k3s --authorization-mode=Node,RBAC --bind-address=127.0.0.1 --cert-dir=/var/lib/rancher/k3s/server/tls/temporary-certs --client-ca-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --egress-selector-config-file=/var/lib/rancher/k3s/server/etc/egress-selector-config.yaml --enable-admission-plugins=NodeRestriction --enable-aggregator-routing=true --enable-bootstrap-token-auth=true --etcd-servers=unix://kine.sock --kubelet-certificate-authority=/var/lib/rancher/k3s/server/tls/server-ca.crt --kubelet-client-certificate=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.crt --kubelet-client-key=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.key --kubelet-preferred-address-types=InternalIP,ExternalIP,Hostname --profiling=false --proxy-client-cert-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt --proxy-client-key-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.key --requestheader-allowed-names=system:auth-proxy --requestheader-client-ca-file=/var/lib/rancher/k3s/server/tls/request-header-ca.crt --requestheader-extra-headers-prefix=X-Remote-Extra- --requestheader-group-headers=X-Remote-Group --requestheader-username-headers=X-Remote-User --secure-port=6444 --service-account-issuer=https://kubernetes.default.svc.cluster.local --service-account-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-account-signing-key-file=/var/lib/rancher/k3s/server/tls/service.current.key --service-cluster-ip-range=10.43.0.0/16 --service-node-port-range=30000-32767 --storage-backend=etcd3 --tls-cert-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt --tls-cipher-suites=TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305,TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305 --tls-private-key-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key" machine # [ 17.386298] k3s[877]: time="2024-05-13T06:00:10Z" 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" machine # [ 17.392205] k3s[877]: time="2024-05-13T06:00:10Z" 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 --use-service-account-credentials=true" machine # [ 17.410676] k3s[877]: time="2024-05-13T06:00:10Z" 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,-service --feature-gates=CloudDualStackNodeIPs=true --kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --leader-elect=false --leader-elect-resource-name=k3s-cloud-controller-manager --node-status-update-frequency=1m0s --profiling=false" machine # [ 17.420713] k3s[877]: I0513 06:00:10.574303 877 options.go:222] external host was not specified, using 10.0.2.15 machine # [ 17.423963] k3s[877]: I0513 06:00:10.577550 877 server.go:156] Version: v1.29.4+k3s1 machine # [ 17.426121] k3s[877]: I0513 06:00:10.579713 877 server.go:158] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 17.435145] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="Waiting for API server to become available" machine # [ 17.439713] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token" machine # [ 17.442782] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="To join server node to cluster: k3s server -s https://10.0.2.15:6443 -t ${SERVER_NODE_TOKEN}" machine # [ 17.446131] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token" machine # [ 17.448628] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="To join agent node to cluster: k3s agent -s https://10.0.2.15:6443 -t ${AGENT_NODE_TOKEN}" machine # [ 17.452138] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml" machine # [ 17.454499] k3s[877]: time="2024-05-13T06:00:10Z" level=info msg="Run: k3s kubectl" machine # [ 17.947852] k3s[877]: I0513 06:00:11.101102 877 plugins.go:157] Loaded 12 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,RuntimeClass,DefaultIngressClass,MutatingAdmissionWebhook. machine # [ 17.952420] k3s[877]: I0513 06:00:11.105984 877 plugins.go:160] Loaded 13 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,PodSecurity,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,ClusterTrustBundleAttest,CertificateSubjectRestriction,ValidatingAdmissionPolicy,ValidatingAdmissionWebhook,ResourceQuota. machine # [ 17.986080] k3s[877]: I0513 06:00:11.139453 877 instance.go:297] Using reconciler: lease machine # [ 18.012256] k3s[877]: I0513 06:00:11.114695 877 shared_informer.go:311] Waiting for caches to sync for node_authorizer machine # [ 18.217848] k3s[877]: I0513 06:00:11.371389 877 handler.go:275] Adding GroupVersion apiextensions.k8s.io v1 to ResourceManager machine # [ 18.221076] k3s[877]: W0513 06:00:11.373609 877 genericapiserver.go:742] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources. machine # [ 18.929141] k3s[877]: time="2024-05-13T06:00:12Z" level=info msg="Password verified locally for node machine" machine # [ 18.931167] k3s[877]: time="2024-05-13T06:00:12Z" level=info msg="certificate CN=machine signed by CN=k3s-server-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:12 +0000 UTC" machine # [ 18.969343] k3s[877]: I0513 06:00:12.122597 877 handler.go:275] Adding GroupVersion v1 to ResourceManager machine # [ 18.971235] k3s[877]: I0513 06:00:12.124383 877 instance.go:693] API group "internal.apiserver.k8s.io" is not enabled, skipping. machine # [ 19.443267] k3s[877]: time="2024-05-13T06:00:12Z" level=info msg="certificate CN=system:node:machine,O=system:nodes signed by CN=k3s-client-ca@1715580009: notBefore=2024-05-13 06:00:09 +0000 UTC notAfter=2025-05-13 06:00:12 +0000 UTC" machine # [ 19.880807] k3s[877]: time="2024-05-13T06:00:13Z" level=info msg="Module overlay was already loaded" machine # [ 19.883440] k3s[877]: time="2024-05-13T06:00:13Z" level=info msg="Module nf_conntrack was already loaded" machine # [ 20.066154] Bridge firewalling registered machine # [ 20.009645] k3s[877]: I0513 06:00:13.162927 877 instance.go:693] API group "resource.k8s.io" is not enabled, skipping. machine # [ 20.020263] k3s[877]: time="2024-05-13T06:00:13Z" level=info msg="Set sysctl 'net/ipv4/conf/all/forwarding' to 1" machine # [ 20.023092] k3s[877]: time="2024-05-13T06:00:13Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_max' to 131072" machine # [ 20.025094] k3s[877]: time="2024-05-13T06:00:13Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400" machine # [ 20.026844] k3s[877]: time="2024-05-13T06:00:13Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_close_wait' to 3600" machine # [ 20.030071] k3s[877]: time="2024-05-13T06:00:13Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log" machine # [ 20.039626] k3s[877]: I0513 06:00:13.192170 877 handler.go:275] Adding GroupVersion authentication.k8s.io v1 to ResourceManager machine # [ 20.042536] k3s[877]: W0513 06:00:13.196126 877 genericapiserver.go:742] Skipping API authentication.k8s.io/v1beta1 because it has no resources. machine # [ 20.044744] k3s[877]: W0513 06:00:13.198337 877 genericapiserver.go:742] Skipping API authentication.k8s.io/v1alpha1 because it has no resources. machine # [ 20.048265] k3s[877]: I0513 06:00:13.201854 877 handler.go:275] Adding GroupVersion authorization.k8s.io v1 to ResourceManager machine # [ 20.050436] k3s[877]: W0513 06:00:13.204011 877 genericapiserver.go:742] Skipping API authorization.k8s.io/v1beta1 because it has no resources. machine # [ 20.052815] k3s[877]: I0513 06:00:13.206393 877 handler.go:275] Adding GroupVersion autoscaling v2 to ResourceManager machine # [ 20.054810] k3s[877]: I0513 06:00:13.208390 877 handler.go:275] Adding GroupVersion autoscaling v1 to ResourceManager machine # [ 20.056621] k3s[877]: W0513 06:00:13.210212 877 genericapiserver.go:742] Skipping API autoscaling/v2beta1 because it has no resources. machine # [ 20.062582] k3s[877]: W0513 06:00:13.216170 877 genericapiserver.go:742] Skipping API autoscaling/v2beta2 because it has no resources. machine # [ 20.068178] k3s[877]: I0513 06:00:13.221733 877 handler.go:275] Adding GroupVersion batch v1 to ResourceManager machine # [ 20.070685] k3s[877]: W0513 06:00:13.224277 877 genericapiserver.go:742] Skipping API batch/v1beta1 because it has no resources. machine # [ 20.074562] k3s[877]: I0513 06:00:13.228118 877 handler.go:275] Adding GroupVersion certificates.k8s.io v1 to ResourceManager machine # [ 20.078172] k3s[877]: W0513 06:00:13.231750 877 genericapiserver.go:742] Skipping API certificates.k8s.io/v1beta1 because it has no resources. machine # [ 20.079945] k3s[877]: W0513 06:00:13.233537 877 genericapiserver.go:742] Skipping API certificates.k8s.io/v1alpha1 because it has no resources. machine # [ 20.082708] k3s[877]: I0513 06:00:13.236171 877 handler.go:275] Adding GroupVersion coordination.k8s.io v1 to ResourceManager machine # [ 20.085413] k3s[877]: W0513 06:00:13.236190 877 genericapiserver.go:742] Skipping API coordination.k8s.io/v1beta1 because it has no resources. machine # [ 20.088376] k3s[877]: W0513 06:00:13.236264 877 genericapiserver.go:742] Skipping API discovery.k8s.io/v1beta1 because it has no resources. machine # [ 20.092192] k3s[877]: time="2024-05-13T06:00:13Z" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml -a /run/k3s/containerd/containerd.sock --state /run/k3s/containerd --root /var/lib/rancher/k3s/agent/containerd" machine # [ 20.100835] k3s[877]: I0513 06:00:13.254398 877 handler.go:275] Adding GroupVersion discovery.k8s.io v1 to ResourceManager machine # [ 20.105603] k3s[877]: I0513 06:00:13.259189 877 handler.go:275] Adding GroupVersion networking.k8s.io v1 to ResourceManager machine # [ 20.108427] k3s[877]: W0513 06:00:13.261957 877 genericapiserver.go:742] Skipping API networking.k8s.io/v1beta1 because it has no resources. machine # [ 20.110902] k3s[877]: W0513 06:00:13.264398 877 genericapiserver.go:742] Skipping API networking.k8s.io/v1alpha1 because it has no resources. machine # [ 20.116487] k3s[877]: I0513 06:00:13.270073 877 handler.go:275] Adding GroupVersion node.k8s.io v1 to ResourceManager machine # [ 20.118454] k3s[877]: W0513 06:00:13.272031 877 genericapiserver.go:742] Skipping API node.k8s.io/v1beta1 because it has no resources. machine # [ 20.121243] k3s[877]: W0513 06:00:13.274836 877 genericapiserver.go:742] Skipping API node.k8s.io/v1alpha1 because it has no resources. machine # [ 20.124767] k3s[877]: I0513 06:00:13.278358 877 handler.go:275] Adding GroupVersion policy v1 to ResourceManager machine # [ 20.126900] k3s[877]: W0513 06:00:13.278464 877 genericapiserver.go:742] Skipping API policy/v1beta1 because it has no resources. machine # [ 20.133515] k3s[877]: I0513 06:00:13.287030 877 handler.go:275] Adding GroupVersion rbac.authorization.k8s.io v1 to ResourceManager machine # [ 20.135904] k3s[877]: W0513 06:00:13.289494 877 genericapiserver.go:742] Skipping API rbac.authorization.k8s.io/v1beta1 because it has no resources. machine # [ 20.138389] k3s[877]: W0513 06:00:13.291978 877 genericapiserver.go:742] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources. machine # [ 20.142157] k3s[877]: I0513 06:00:13.295734 877 handler.go:275] Adding GroupVersion scheduling.k8s.io v1 to ResourceManager machine # [ 20.144428] k3s[877]: W0513 06:00:13.298021 877 genericapiserver.go:742] Skipping API scheduling.k8s.io/v1beta1 because it has no resources. machine # [ 20.147285] k3s[877]: W0513 06:00:13.300876 877 genericapiserver.go:742] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources. machine # [ 20.151485] k3s[877]: I0513 06:00:13.305040 877 handler.go:275] Adding GroupVersion storage.k8s.io v1 to ResourceManager machine # [ 20.154354] k3s[877]: W0513 06:00:13.307945 877 genericapiserver.go:742] Skipping API storage.k8s.io/v1beta1 because it has no resources. machine # [ 20.156642] k3s[877]: W0513 06:00:13.310232 877 genericapiserver.go:742] Skipping API storage.k8s.io/v1alpha1 because it has no resources. machine # [ 20.161147] k3s[877]: I0513 06:00:13.314607 877 handler.go:275] Adding GroupVersion flowcontrol.apiserver.k8s.io v1beta3 to ResourceManager machine # [ 20.164992] k3s[877]: I0513 06:00:13.318578 877 handler.go:275] Adding GroupVersion flowcontrol.apiserver.k8s.io v1 to ResourceManager machine # [ 20.169092] k3s[877]: W0513 06:00:13.322678 877 genericapiserver.go:742] Skipping API flowcontrol.apiserver.k8s.io/v1beta2 because it has no resources. machine # [ 20.172300] k3s[877]: W0513 06:00:13.325891 877 genericapiserver.go:742] Skipping API flowcontrol.apiserver.k8s.io/v1beta1 because it has no resources. machine # [ 20.182523] k3s[877]: I0513 06:00:13.336098 877 handler.go:275] Adding GroupVersion apps v1 to ResourceManager machine # [ 20.185892] k3s[877]: W0513 06:00:13.339462 877 genericapiserver.go:742] Skipping API apps/v1beta2 because it has no resources. machine # [ 20.188057] k3s[877]: W0513 06:00:13.341392 877 genericapiserver.go:742] Skipping API apps/v1beta1 because it has no resources. machine # [ 20.192068] k3s[877]: I0513 06:00:13.345216 877 handler.go:275] Adding GroupVersion admissionregistration.k8s.io v1 to ResourceManager machine # [ 20.194906] k3s[877]: W0513 06:00:13.345238 877 genericapiserver.go:742] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources. machine # [ 20.198052] k3s[877]: W0513 06:00:13.345252 877 genericapiserver.go:742] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources. machine # [ 20.205055] k3s[877]: I0513 06:00:13.358613 877 handler.go:275] Adding GroupVersion events.k8s.io v1 to ResourceManager machine # [ 20.207774] k3s[877]: W0513 06:00:13.361349 877 genericapiserver.go:742] Skipping API events.k8s.io/v1beta1 because it has no resources. machine # [ 20.216628] k3s[877]: I0513 06:00:13.370207 877 handler.go:275] Adding GroupVersion apiregistration.k8s.io v1 to ResourceManager machine # [ 20.222772] k3s[877]: W0513 06:00:13.376345 877 genericapiserver.go:742] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources. machine # [ 21.054688] k3s[877]: I0513 06:00:14.207950 877 secure_serving.go:213] Serving securely on 127.0.0.1:6444 machine # [ 21.057245] k3s[877]: I0513 06:00:14.210297 877 dynamic_cafile_content.go:157] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt" machine # [ 21.060542] k3s[877]: I0513 06:00:14.210437 877 dynamic_serving_content.go:132] "Starting controller" name="serving-cert::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key" machine # [ 21.065389] k3s[877]: I0513 06:00:14.210540 877 tlsconfig.go:240] "Starting DynamicServingCertificateController" machine # [ 21.067435] k3s[877]: I0513 06:00:14.221019 877 apf_controller.go:374] Starting API Priority and Fairness config controller machine # [ 21.071474] k3s[877]: I0513 06:00:14.225059 877 controller.go:116] Starting legacy_token_tracking_controller machine # [ 21.073577] k3s[877]: I0513 06:00:14.227171 877 shared_informer.go:311] Waiting for caches to sync for configmaps machine # [ 21.075326] k3s[877]: I0513 06:00:14.228919 877 cluster_authentication_trust_controller.go:440] Starting cluster_authentication_trust_controller controller machine # [ 21.078667] k3s[877]: I0513 06:00:14.232260 877 shared_informer.go:311] Waiting for caches to sync for cluster_authentication_trust_controller machine # [ 21.081883] k3s[877]: I0513 06:00:14.235475 877 available_controller.go:423] Starting AvailableConditionController machine # [ 21.084076] k3s[877]: I0513 06:00:14.237670 877 cache.go:32] Waiting for caches to sync for AvailableConditionController controller machine # [ 21.085741] k3s[877]: I0513 06:00:14.239335 877 controller.go:80] Starting OpenAPI V3 AggregationController machine # [ 21.088114] k3s[877]: I0513 06:00:14.241706 877 gc_controller.go:78] Starting apiserver lease garbage collector machine # [ 21.090753] k3s[877]: I0513 06:00:14.244336 877 system_namespaces_controller.go:67] Starting system namespaces controller machine # [ 21.093518] k3s[877]: I0513 06:00:14.247108 877 dynamic_serving_content.go:132] "Starting controller" name="aggregator-proxy-cert::/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt::/var/lib/rancher/k3s/server/tls/client-auth-proxy.key" machine # [ 21.098523] k3s[877]: I0513 06:00:14.252116 877 aggregator.go:163] waiting for initial CRD sync... machine # [ 21.100450] k3s[877]: I0513 06:00:14.254042 877 controller.go:78] Starting OpenAPI AggregationController machine # [ 21.102361] k3s[877]: I0513 06:00:14.255953 877 customresource_discovery_controller.go:289] Starting DiscoveryController machine # [ 21.104728] k3s[877]: I0513 06:00:14.258321 877 apiservice_controller.go:97] Starting APIServiceRegistrationController machine # [ 21.107311] k3s[877]: I0513 06:00:14.260904 877 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller machine # [ 21.110378] k3s[877]: I0513 06:00:14.263971 877 handler_discovery.go:412] Starting ResourceDiscoveryManager machine # [ 21.112972] k3s[877]: I0513 06:00:14.266563 877 dynamic_cafile_content.go:157] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt" machine # [ 21.123355] k3s[877]: I0513 06:00:14.276931 877 dynamic_cafile_content.go:157] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt" machine # [ 21.127193] k3s[877]: I0513 06:00:14.280784 877 dynamic_cafile_content.go:157] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt" machine # [ 21.132154] k3s[877]: I0513 06:00:14.285746 877 crdregistration_controller.go:111] Starting crd-autoregister controller machine # [ 21.134920] k3s[877]: I0513 06:00:14.288512 877 shared_informer.go:311] Waiting for caches to sync for crd-autoregister machine # [ 21.138092] k3s[877]: I0513 06:00:14.291684 877 controller.go:133] Starting OpenAPI controller machine # [ 21.139506] k3s[877]: I0513 06:00:14.293099 877 controller.go:85] Starting OpenAPI V3 controller machine # [ 21.141663] k3s[877]: I0513 06:00:14.295246 877 naming_controller.go:291] Starting NamingConditionController machine # [ 21.144184] k3s[877]: I0513 06:00:14.297777 877 establishing_controller.go:76] Starting EstablishingController machine # [ 21.146286] k3s[877]: I0513 06:00:14.299879 877 nonstructuralschema_controller.go:192] Starting NonStructuralSchemaConditionController machine # [ 21.148040] k3s[877]: I0513 06:00:14.301603 877 apiapproval_controller.go:186] Starting KubernetesAPIApprovalPolicyConformantConditionController machine # [ 21.149845] k3s[877]: I0513 06:00:14.303430 877 crd_finalizer.go:266] Starting CRDFinalizer machine # [ 21.222444] k3s[877]: time="2024-05-13T06:00:14Z" level=info msg="containerd is now running" machine # [ 21.239400] k3s[877]: time="2024-05-13T06:00:14Z" level=info msg="Connecting to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 21.242986] k3s[877]: time="2024-05-13T06:00:14Z" level=info msg="Creating k3s-cert-monitor event broadcaster" machine # [ 21.269980] k3s[877]: time="2024-05-13T06:00:14Z" level=info msg="Running kubelet --address=0.0.0.0 --anonymous-auth=false --authentication-token-webhook=true --authorization-mode=Webhook --cgroup-driver=systemd --client-ca-file=/var/lib/rancher/k3s/agent/client-ca.crt --cloud-provider=external --cluster-dns=10.43.0.10 --cluster-domain=cluster.local --container-runtime-endpoint=unix:///run/k3s/containerd/containerd.sock --containerd=/run/k3s/containerd/containerd.sock --eviction-hard=imagefs.available<5%,nodefs.available<5% --eviction-minimum-reclaim=imagefs.available=10%,nodefs.available=10% --fail-swap-on=false --feature-gates=CloudDualStackNodeIPs=true --healthz-bind-address=127.0.0.1 --hostname-override=machine --kubeconfig=/var/lib/rancher/k3s/agent/kubelet.kubeconfig --node-ip=10.0.2.15,fec0::1620:efe5:3e6d:8a9 --node-labels= --pod-infra-container-image=test.local/pause:local --pod-manifest-path=/var/lib/rancher/k3s/agent/pod-manifests --read-only-port=0 --resolv-conf=/etc/resolv.conf --serialize-image-pulls=false --tls-cert-file=/var/lib/rancher/k3s/agent/serving-kubelet.crt --tls-private-key-file=/var/lib/rancher/k3s/agent/serving-kubelet.key" machine # [ 21.315550] k3s[877]: I0513 06:00:14.469043 877 shared_informer.go:318] Caches are synced for node_authorizer machine # [ 21.331364] k3s[877]: I0513 06:00:14.484932 877 shared_informer.go:318] Caches are synced for cluster_authentication_trust_controller machine # [ 21.336495] k3s[877]: I0513 06:00:14.490083 877 cache.go:39] Caches are synced for AvailableConditionController controller machine # [ 21.339254] k3s[877]: I0513 06:00:14.492847 877 shared_informer.go:318] Caches are synced for crd-autoregister machine # [ 21.342440] k3s[877]: I0513 06:00:14.496033 877 aggregator.go:165] initial CRD sync complete... machine # [ 21.344129] k3s[877]: I0513 06:00:14.497714 877 autoregister_controller.go:141] Starting autoregister controller machine # [ 21.345587] k3s[877]: I0513 06:00:14.499181 877 cache.go:32] Waiting for caches to sync for autoregister controller machine # [ 21.349074] k3s[877]: I0513 06:00:14.502452 877 cache.go:39] Caches are synced for autoregister controller machine # [ 21.352653] k3s[877]: I0513 06:00:14.506216 877 cache.go:39] Caches are synced for APIServiceRegistrationController controller machine # [ 21.376078] k3s[877]: I0513 06:00:14.528807 877 shared_informer.go:318] Caches are synced for configmaps machine # [ 21.384190] k3s[877]: I0513 06:00:14.537745 877 apf_controller.go:379] Running API Priority and Fairness config worker machine # [ 21.386265] k3s[877]: I0513 06:00:14.539858 877 apf_controller.go:382] Running API Priority and Fairness periodic rebalancing process machine # [ 21.404846] k3s[877]: time="2024-05-13T06:00:14Z" level=info msg="Handling backend connection request [machine]" machine # [ 21.423598] k3s[877]: I0513 06:00:14.577109 877 controller.go:624] quota admission added evaluator for: namespaces machine # [ 21.447473] k3s[877]: time="2024-05-13T06:00:14Z" level=info msg="Remotedialer connected to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 21.492168] k3s[877]: E0513 06:00:14.645729 877 controller.go:95] Unable to perform initial Kubernetes service initialization: namespaces "default" not found machine # [ 21.516859] k3s[877]: E0513 06:00:14.670405 877 controller.go:145] while syncing ConfigMap "kube-system/kube-apiserver-legacy-service-account-token-tracking", err: namespaces "kube-system" not found machine # [ 21.643376] k3s[877]: I0513 06:00:14.796859 877 controller.go:624] quota admission added evaluator for: leases.coordination.k8s.io machine # [ 21.716774] k3s[877]: time="2024-05-13T06:00:14Z" level=info msg="Waiting to retrieve kube-proxy configuration; server is not ready: https://127.0.0.1:6443/v1-k3s/readyz: 500 Internal Server Error" machine # [ 22.084362] k3s[877]: I0513 06:00:15.237280 877 storage_scheduling.go:95] created PriorityClass system-node-critical with value 2000001000 machine # [ 22.097497] k3s[877]: I0513 06:00:15.251065 877 storage_scheduling.go:95] created PriorityClass system-cluster-critical with value 2000000000 machine # [ 22.100073] k3s[877]: I0513 06:00:15.253629 877 storage_scheduling.go:111] all system priority classes are created successfully or already exist. machine # [ 22.851636] k3s[877]: I0513 06:00:16.005194 877 controller.go:624] quota admission added evaluator for: roles.rbac.authorization.k8s.io machine # [ 22.905097] k3s[877]: I0513 06:00:16.058014 877 controller.go:624] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io machine # [ 23.032481] k3s[877]: I0513 06:00:16.186029 877 alloc.go:330] "allocated clusterIPs" service="default/kubernetes" clusterIPs={"IPv4":"10.43.0.1"} machine # [ 23.050832] k3s[877]: W0513 06:00:16.200828 877 lease.go:265] Resetting endpoints for master service "kubernetes" to [10.0.2.15] machine # [ 23.060943] k3s[877]: I0513 06:00:16.214526 877 controller.go:624] quota admission added evaluator for: endpoints machine # [ 23.082666] k3s[877]: I0513 06:00:16.236199 877 controller.go:624] quota admission added evaluator for: endpointslices.discovery.k8s.io machine # [ 23.463428] k3s[877]: Flag --containerd has been deprecated, This is a cadvisor flag that was mistakenly registered with the Kubelet. Due to legacy concerns, it will follow the standard CLI deprecation timeline before being removed. machine # [ 23.467269] k3s[877]: Flag --pod-infra-container-image has been deprecated, will be removed in a future release. Image garbage collector will get sandbox image information from CRI. machine # [ 23.469707] k3s[877]: I0513 06:00:16.616485 877 server.go:203] "--pod-infra-container-image will not be pruned by the image garbage collector in kubelet and should also be set in the remote runtime" machine # [ 23.493389] k3s[877]: I0513 06:00:16.646935 877 server.go:482] "Kubelet version" kubeletVersion="v1.29.4+k3s1" machine # [ 23.496607] k3s[877]: I0513 06:00:16.650193 877 server.go:484] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 23.502507] k3s[877]: I0513 06:00:16.656058 877 dynamic_cafile_content.go:157] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt" machine # [ 23.523143] k3s[877]: time="2024-05-13T06:00:16Z" level=info msg="Kube API server is now running" machine # [ 23.525784] k3s[877]: time="2024-05-13T06:00:16Z" level=info msg="ETCD server is now running" machine # [ 23.527330] k3s[877]: time="2024-05-13T06:00:16Z" level=info msg="k3s is up and running" machine # [ 23.532887] systemd[1]: Started k3s service. machine # [ 23.534395] systemd[1]: Reached target Multi-User System. machine # [ 23.536199] systemd[1]: Startup finished in 3.965s (kernel) + 19.565s (userspace) = 23.530s. machine # [ 23.538996] k3s[877]: time="2024-05-13T06:00:16Z" level=info msg="Creating k3s-supervisor event broadcaster" machine # [ 23.541907] k3s[877]: time="2024-05-13T06:00:16Z" level=info msg="Waiting for cloud-controller-manager privileges to become available" machine # [ 23.631840] k3s[877]: I0513 06:00:16.785388 877 server.go:740] "--cgroups-per-qos enabled, but --cgroup-root was not specified. defaulting to /" machine # [ 23.636338] k3s[877]: I0513 06:00:16.789921 877 container_manager_linux.go:265] "Container manager verified user specified cgroup-root exists" cgroupRoot=[] machine # [ 23.641582] k3s[877]: I0513 06:00:16.795126 877 container_manager_linux.go:270] "Creating Container Manager object based on Node Config" nodeConfig={"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,"ExperimentalMemoryManagerPolicy":"None","ExperimentalMemoryManagerReservedMemory":null,"PodPidsLimit":-1,"EnforceCPULimits":true,"CPUCFSQuotaPeriod":100000000,"TopologyManagerPolicy":"none","TopologyManagerPolicyOptions":null} machine # [ 23.688275] k3s[877]: I0513 06:00:16.841837 877 topology_manager.go:138] "Creating topology manager with none policy" machine # [ 23.691290] k3s[877]: I0513 06:00:16.844859 877 container_manager_linux.go:301] "Creating device plugin manager" machine # [ 23.694505] k3s[877]: I0513 06:00:16.846830 877 state_mem.go:36] "Initialized new in-memory state store" machine # [ 23.696264] k3s[877]: I0513 06:00:16.847001 877 kubelet.go:396] "Attempting to sync node with API server" machine # [ 23.698120] k3s[877]: I0513 06:00:16.847031 877 kubelet.go:301] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests" machine # [ 23.701239] k3s[877]: I0513 06:00:16.847089 877 kubelet.go:312] "Adding apiserver pod source" machine # [ 23.702769] k3s[877]: I0513 06:00:16.847124 877 apiserver.go:42] "Waiting for node sync before watching apiserver pods" (finished: waiting for unit k3s, in 24.38 seconds) machine: must succeed: kubectl cluster-info machine # [ 23.782664] k3s[877]: I0513 06:00:16.935470 877 kuberuntime_manager.go:258] "Container runtime initialized" containerRuntime="containerd" version="v1.7.15-k3s1" apiVersion="v1" machine # [ 23.788277] k3s[877]: I0513 06:00:16.938905 877 kubelet.go:809] "Not starting ClusterTrustBundle informer because we are in static kubelet mode" machine # [ 23.790103] k3s[877]: W0513 06:00:16.938973 877 probe.go:268] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating. machine # [ 23.821082] k3s[877]: I0513 06:00:16.973830 877 server.go:1251] "Started kubelet" machine # [ 23.835820] k3s[877]: I0513 06:00:16.989292 877 server.go:162] "Starting to listen" address="0.0.0.0" port=10250 machine # [ 23.841962] k3s[877]: I0513 06:00:16.995549 877 server.go:461] "Adding debug handlers to kubelet server" machine # [ 23.902055] k3s[877]: I0513 06:00:17.004119 877 ratelimit.go:55] "Setting rate limiting for endpoint" service="podresources" qps=100 burstTokens=10 machine # [ 23.905530] k3s[877]: I0513 06:00:17.058894 877 server.go:233] "Starting to serve the podresources API" endpoint="unix:/var/lib/kubelet/pod-resources/kubelet.sock" machine # [ 23.907969] k3s[877]: I0513 06:00:17.006229 877 fs_resource_analyzer.go:67] "Starting FS ResourceAnalyzer" machine # [ 23.923072] k3s[877]: I0513 06:00:17.075110 877 volume_manager.go:291] "Starting Kubelet Volume Manager" machine # [ 23.941204] k3s[877]: I0513 06:00:17.094784 877 desired_state_of_world_populator.go:151] "Desired state populator starts to run" machine # [ 23.943124] k3s[877]: I0513 06:00:17.096717 877 reconciler_new.go:29] "Reconciler: start to sync state" machine # [ 24.024694] k3s[877]: I0513 06:00:17.176495 877 factory.go:221] Registration of the systemd container factory successfully machine # [ 24.026402] k3s[877]: I0513 06:00:17.176776 877 factory.go:219] Registration of the crio container factory failed: Get "http://%2Fvar%2Frun%2Fcrio%2Fcrio.sock/info": dial unix /var/run/crio/crio.sock: connect: no such file or directory machine # [ 24.048704] k3s[877]: E0513 06:00:17.202221 877 container_manager_linux.go:881] "Unable to get rootfs data from cAdvisor interface" err="unable to find data in memory cache" machine # [ 24.058693] k3s[877]: I0513 06:00:17.212283 877 factory.go:221] Registration of the containerd container factory successfully machine # [ 24.117969] k3s[877]: I0513 06:00:17.271535 877 kubelet_node_status.go:73] "Attempting to register node" node="machine" machine # [ 24.267459] k3s[877]: I0513 06:00:17.421030 877 kubelet_network_linux.go:50] "Initialized iptables rules." protocol="IPv4" machine # [ 24.289170] k3s[877]: I0513 06:00:17.442758 877 kubelet_network_linux.go:50] "Initialized iptables rules." protocol="IPv6" machine # [ 24.291194] k3s[877]: I0513 06:00:17.444196 877 status_manager.go:217] "Starting to sync pod status with apiserver" machine # [ 24.292623] k3s[877]: I0513 06:00:17.444232 877 kubelet.go:2329] "Starting kubelet main sync loop" machine # [ 24.293836] k3s[877]: E0513 06:00:17.444283 877 kubelet.go:2353] "Skipping pod synchronization" err="[container runtime status check may not have completed yet, PLEG is not healthy: pleg has yet to be successful]" machine # [ 24.400604] k3s[877]: E0513 06:00:17.552945 877 kubelet.go:2353] "Skipping pod synchronization" err="[container runtime status check may not have completed yet, PLEG is not healthy: pleg has yet to be successful]" machine # [ 24.403377] k3s[877]: time="2024-05-13T06:00:17Z" level=info msg="Applying CRD addons.k3s.cattle.io" machine # [ 24.443353] k3s[877]: I0513 06:00:17.596938 877 cpu_manager.go:214] "Starting CPU manager" policy="none" machine # [ 24.444813] k3s[877]: I0513 06:00:17.598399 877 cpu_manager.go:215] "Reconciling" reconcilePeriod="10s" machine # [ 24.446521] k3s[877]: I0513 06:00:17.599613 877 state_mem.go:36] "Initialized new in-memory state store" machine # [ 24.450399] k3s[877]: I0513 06:00:17.603219 877 policy_none.go:49] "None policy: Start" machine # [ 24.462034] k3s[877]: I0513 06:00:17.615598 877 kubelet_node_status.go:76] "Successfully registered node" node="machine" machine # [ 24.573220] k3s[877]: I0513 06:00:17.726486 877 memory_manager.go:170] "Starting memorymanager" policy="None" machine # [ 24.575558] k3s[877]: I0513 06:00:17.728851 877 state_mem.go:35] "Initializing new in-memory state store" (finished: must succeed: kubectl cluster-info, in 0.85 seconds) machine: must fail: sudo -u noprivs kubectl cluster-info machine # [ 24.600067] k3s[877]: I0513 06:00:17.753261 877 serving.go:387] Generated self-signed cert in-memory machine # [ 24.604343] k3s[877]: E0513 06:00:17.757913 877 kubelet.go:2353] "Skipping pod synchronization" err="container runtime status check may not have completed yet" machine # [ 24.607848] k3s[877]: time="2024-05-13T06:00:17Z" level=info msg="Annotations and labels have been set successfully on node: machine" machine # [ 24.614065] k3s[877]: time="2024-05-13T06:00:17Z" level=info msg="Starting flannel with backend vxlan" machine # [ 24.690872] sudo[996]: root : TTY=hvc0 ; PWD=/tmp ; USER=noprivs ; COMMAND=/run/current-system/sw/bin/kubectl cluster-info machine # [ 24.710471] sudo[996]: pam_unix(sudo:session): session opened for user noprivs(uid=1000) by (uid=0) machine # [ 24.726313] k3s[877]: I0513 06:00:17.879607 877 apiserver.go:52] "Watching apiserver" machine # [ 24.763711] systemd[1]: Created slice libcontainer container kubepods.slice. machine # [ 24.956809] systemd[1]: Created slice libcontainer container kubepods-burstable.slice. machine # [ 25.013252] k3s[877]: E0513 06:00:18.166773 877 kubelet.go:2353] "Skipping pod synchronization" err="container runtime status check may not have completed yet" machine # WARN[0000] Unable to read /etc/rancher/k3s/k3s.yaml, please start server with --write-kubeconfig-mode to modify kube config permissions machine # error: error loading config file "/etc/rancher/k3s/k3s.yaml": open /etc/rancher/k3s/k3s.yaml: permission denied machine # [ 25.102339] systemd[1]: Created slice libcontainer container kubepods-besteffort.slice. machine # [ 25.127223] sudo[996]: pam_unix(sudo:session): session closed for user noprivs (finished: must fail: sudo -u noprivs kubectl cluster-info, in 0.55 seconds) machine: must succeed: k3s check-config machine # [ 25.209958] k3s[877]: I0513 06:00:18.362207 877 manager.go:479] "Failed to read data from checkpoint" checkpoint="kubelet_internal_checkpoint" err="checkpoint is not found" machine # [ 25.213257] k3s[877]: I0513 06:00:18.366394 877 plugin_manager.go:118] "Starting Kubelet Plugin Manager" machine # [ 25.230784] k3s[877]: time="2024-05-13T06:00:18Z" level=info msg="Applying CRD etcdsnapshotfiles.k3s.cattle.io" machine # cat: /sys/kernel/security/apparmor/profiles: No such file or directory machine # [ 25.312761] k3s[877]: I0513 06:00:18.466087 877 kubelet_node_status.go:497] "Fast updating node status as it just became ready" machine # [ 25.360138] k3s[877]: I0513 06:00:18.513615 877 handler.go:275] Adding GroupVersion k3s.cattle.io v1 to ResourceManager machine # [ 25.761190] k3s[877]: time="2024-05-13T06:00:18Z" level=info msg="Applying CRD helmcharts.helm.cattle.io" machine # [ 25.846242] k3s[877]: I0513 06:00:18.999819 877 handler.go:275] Adding GroupVersion k3s.cattle.io v1 to ResourceManager machine # [ 25.848460] k3s[877]: I0513 06:00:19.002050 877 desired_state_of_world_populator.go:159] "Finished populating initial desired state of world" machine # [ 26.374337] k3s[877]: time="2024-05-13T06:00:19Z" level=info msg="Applying CRD helmchartconfigs.helm.cattle.io" machine # [ 26.511645] k3s[877]: I0513 06:00:19.665204 877 controllermanager.go:187] "Starting" version="v1.29.4+k3s1" machine # [ 26.568539] k3s[877]: I0513 06:00:19.721822 877 controllermanager.go:189] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 26.577510] k3s[877]: I0513 06:00:19.721341 877 handler.go:275] Adding GroupVersion helm.cattle.io v1 to ResourceManager machine # [ 26.621842] k3s[877]: I0513 06:00:19.775373 877 secure_serving.go:213] Serving securely on 127.0.0.1:10257 machine # [ 26.628388] k3s[877]: I0513 06:00:19.780828 877 requestheader_controller.go:169] Starting RequestHeaderAuthRequestController machine # [ 26.630491] k3s[877]: I0513 06:00:19.780860 877 shared_informer.go:311] Waiting for caches to sync for RequestHeaderAuthRequestController machine # [ 26.632673] k3s[877]: I0513 06:00:19.780909 877 tlsconfig.go:240] "Starting DynamicServingCertificateController" machine # [ 26.643092] k3s[877]: I0513 06:00:19.795706 877 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 26.645917] k3s[877]: I0513 06:00:19.795751 877 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::client-ca-file machine # [ 26.648573] k3s[877]: I0513 06:00:19.795820 877 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 26.652184] k3s[877]: I0513 06:00:19.795839 877 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file machine # [ 26.727546] k3s[877]: I0513 06:00:19.881102 877 shared_informer.go:318] Caches are synced for RequestHeaderAuthRequestController machine # [ 26.753496] k3s[877]: I0513 06:00:19.906612 877 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::client-ca-file machine # [ 26.757309] k3s[877]: I0513 06:00:19.906977 877 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file machine # [ 26.803414] k3s[877]: I0513 06:00:19.955498 877 controllermanager.go:735] "Started controller" controller="serviceaccount-token-controller" machine # [ 26.806642] k3s[877]: I0513 06:00:19.959878 877 handler.go:275] Adding GroupVersion helm.cattle.io v1 to ResourceManager machine # [ 26.810072] k3s[877]: I0513 06:00:19.962891 877 shared_informer.go:311] Waiting for caches to sync for tokens machine # [ 26.834097] k3s[877]: time="2024-05-13T06:00:19Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-25.0.3+up25.0.0.tgz" machine # [ 26.839490] k3s[877]: time="2024-05-13T06:00:19Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-25.0.3+up25.0.0.tgz" machine # [ 26.844102] k3s[877]: time="2024-05-13T06:00:19Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml" machine # [ 26.847622] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/runtimes.yaml" machine # [ 26.851091] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml" machine # [ 26.870181] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Starting dynamiclistener CN filter node controller" machine # [ 26.888392] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Tunnel server egress proxy mode: agent" machine # [ 26.909460] k3s[877]: I0513 06:00:20.062998 877 shared_informer.go:318] Caches are synced for tokens machine # [ 27.103099] k3s[877]: I0513 06:00:20.256006 877 controller.go:624] quota admission added evaluator for: serviceaccounts machine # [ 27.245126] k3s[877]: I0513 06:00:20.398559 877 controllermanager.go:735] "Started controller" controller="persistentvolumeclaim-protection-controller" machine # [ 27.248083] k3s[877]: I0513 06:00:20.401043 877 controllermanager.go:687] "Controller is disabled by a feature gate" controller="resourceclaim-controller" requiredFeatureGates=["DynamicResourceAllocation"] machine # [ 27.251234] k3s[877]: I0513 06:00:20.401579 877 pvc_protection_controller.go:102] "Starting PVC protection controller" machine # [ 27.254206] k3s[877]: I0513 06:00:20.401600 877 shared_informer.go:311] Waiting for caches to sync for PVC protection machine # [ 27.327305] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller" machine # [ 27.331078] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Creating deploy event broadcaster" machine # [ 27.342322] k3s[877]: I0513 06:00:20.495395 877 controller.go:624] quota admission added evaluator for: addons.k3s.cattle.io machine # [ 27.387115] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Starting /v1, Kind=Node controller" machine # [ 27.390290] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Starting /v1, Kind=Secret controller" machine # [ 27.397871] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Creating helm-controller event broadcaster" machine # [ 27.776765] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Updating 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__1620_efe5_3e6d_8a9-103756:fec0::1620:efe5:3e6d:8a9 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=EC846238A342F5889C1143BD676C6A7AE04E445E]" machine # [ 27.793073] k3s[877]: time="2024-05-13T06:00:20Z" level=info msg="Updating 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__1620_efe5_3e6d_8a9-103756:fec0::1620:efe5:3e6d:8a9 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=EC846238A342F5889C1143BD676C6A7AE04E445E]" machine # [ 28.003547] k3s[877]: I0513 06:00:21.156822 877 event.go:376] "Event occurred" object="kube-system/ccm" fieldPath="" kind="Addon" apiVersion="k3s.cattle.io/v1" type="Normal" reason="ApplyingManifest" message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" machine # [ 28.163918] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Active TLS secret kube-system/k3s-serving (ver=227) (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__1620_efe5_3e6d_8a9-103756:fec0::1620:efe5:3e6d:8a9 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=EC846238A342F5889C1143BD676C6A7AE04E445E]" machine # [ 28.225720] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Cluster dns configmap has been set successfully" machine # [ 28.230189] k3s[877]: I0513 06:00:21.383769 877 controllermanager.go:735] "Started controller" controller="taint-eviction-controller" machine # [ 28.240029] k3s[877]: I0513 06:00:21.392712 877 taint_eviction.go:285] "Starting" controller="taint-eviction-controller" machine # [ 28.246569] k3s[877]: I0513 06:00:21.400063 877 taint_eviction.go:291] "Sending events to api server" machine # [ 28.249628] k3s[877]: I0513 06:00:21.403210 877 shared_informer.go:311] Waiting for caches to sync for taint-eviction-controller machine # [ 28.324831] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Labels and annotations have been set successfully on node: machine" machine # [ 28.409101] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Running kube-proxy --cluster-cidr=10.42.0.0/16 --conntrack-max-per-core=0 --conntrack-tcp-timeout-close-wait=0s --conntrack-tcp-timeout-established=0s --healthz-bind-address=127.0.0.1 --hostname-override=machine --kubeconfig=/var/lib/rancher/k3s/agent/kubeproxy.kubeconfig --proxy-mode=iptables" machine # [ 28.431682] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller" machine # [ 28.435859] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller" machine # [ 28.478835] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Starting rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding controller" machine # [ 28.500086] k3s[877]: I0513 06:00:21.653535 877 server.go:1050] "Successfully retrieved node IP(s)" IPs=["10.0.2.15","fec0::1620:efe5:3e6d:8a9"] machine # [ 28.564656] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Starting batch/v1, Kind=Job controller" machine # [ 28.566546] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Starting /v1, Kind=ConfigMap controller" machine # [ 28.570074] k3s[877]: time="2024-05-13T06:00:21Z" level=info msg="Starting /v1, Kind=ServiceAccount controller" machine # [ 28.634856] k3s[877]: I0513 06:00:21.788359 877 server.go:652] "kube-proxy running in dual-stack mode" primary ipFamily="IPv4" machine # [ 28.636959] k3s[877]: I0513 06:00:21.788398 877 server_others.go:168] "Using iptables Proxier" machine # [ 28.689351] k3s[877]: I0513 06:00:21.842828 877 server_others.go:512] "Detect-local-mode set to ClusterCIDR, but no cluster CIDR for family" ipFamily="IPv6" machine # [ 28.693194] k3s[877]: I0513 06:00:21.845824 877 server_others.go:529] "Defaulting to no-op detect-local" machine # [ 28.695056] k3s[877]: I0513 06:00:21.845863 877 proxier.go:245] "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" machine # [ 28.699519] k3s[877]: I0513 06:00:21.846207 877 server.go:865] "Version info" version="v1.29.4+k3s1" machine # [ 28.702097] k3s[877]: I0513 06:00:21.846229 877 server.go:867] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 28.742974] k3s[877]: I0513 06:00:21.894984 877 config.go:188] "Starting service config controller" machine # [ 28.744887] k3s[877]: I0513 06:00:21.895014 877 shared_informer.go:311] Waiting for caches to sync for service config machine # [ 28.746899] k3s[877]: I0513 06:00:21.895064 877 config.go:97] "Starting endpoint slice config controller" machine # [ 28.748722] k3s[877]: I0513 06:00:21.895081 877 shared_informer.go:311] Waiting for caches to sync for endpoint slice config machine # [ 28.758255] k3s[877]: I0513 06:00:21.910923 877 config.go:315] "Starting node config controller" machine # [ 28.760369] k3s[877]: I0513 06:00:21.911509 877 shared_informer.go:311] Waiting for caches to sync for node config machine # [ 28.843107] k3s[877]: I0513 06:00:21.996081 877 shared_informer.go:318] Caches are synced for endpoint slice config machine # [ 28.861877] k3s[877]: I0513 06:00:22.013830 877 shared_informer.go:318] Caches are synced for node config machine # [ 28.863792] k3s[877]: I0513 06:00:22.014511 877 shared_informer.go:318] Caches are synced for service config machine # [ 29.197437] k3s[877]: I0513 06:00:22.350559 877 event.go:376] "Event occurred" object="kube-system/ccm" fieldPath="" kind="Addon" apiVersion="k3s.cattle.io/v1" type="Normal" reason="AppliedManifest" message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\"" machine # [ 29.268509] k3s[877]: I0513 06:00:22.421404 877 controllermanager.go:735] "Started controller" controller="horizontal-pod-autoscaler-controller" machine # [ 29.281563] k3s[877]: I0513 06:00:22.435005 877 horizontal.go:200] "Starting HPA controller" machine # [ 29.287543] k3s[877]: I0513 06:00:22.441109 877 shared_informer.go:311] Waiting for caches to sync for HPA machine # [ 30.103190] k3s[877]: I0513 06:00:23.255763 877 event.go:376] "Event occurred" object="kube-system/rolebindings" fieldPath="" kind="Addon" apiVersion="k3s.cattle.io/v1" type="Normal" reason="ApplyingManifest" message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/rolebindings.yaml\"" machine # [ 30.347293] k3s[877]: I0513 06:00:23.499943 877 event.go:376] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="" type="Normal" reason="NodePasswordValidationComplete" message="Deferred node password secret validation complete" machine # [ 30.445738] k3s[877]: I0513 06:00:23.599221 877 controllermanager.go:735] "Started controller" controller="statefulset-controller" machine # [ 30.450140] k3s[877]: I0513 06:00:23.603712 877 stateful_set.go:161] "Starting stateful set controller" machine # [ 30.452471] k3s[877]: I0513 06:00:23.605557 877 shared_informer.go:311] Waiting for caches to sync for stateful set machine # [ 30.703877] k3s[877]: I0513 06:00:23.857343 877 node_lifecycle_controller.go:425] "Controller will reconcile labels" machine # [ 30.707136] k3s[877]: I0513 06:00:23.860718 877 controllermanager.go:735] "Started controller" controller="node-lifecycle-controller" machine # [ 30.710352] k3s[877]: I0513 06:00:23.863453 877 node_lifecycle_controller.go:459] "Sending events to api server" machine # [ 30.713884] k3s[877]: I0513 06:00:23.863503 877 node_lifecycle_controller.go:470] "Starting node controller" machine # [ 30.716872] k3s[877]: I0513 06:00:23.863523 877 shared_informer.go:311] Waiting for caches to sync for taint machine # [ 31.976382] k3s[877]: I0513 06:00:25.129561 877 event.go:376] "Event occurred" object="kube-system/rolebindings" fieldPath="" kind="Addon" apiVersion="k3s.cattle.io/v1" type="Normal" reason="AppliedManifest" message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/rolebindings.yaml\"" machine # [ 32.141698] k3s[877]: I0513 06:00:25.294302 877 serving.go:387] Generated self-signed cert in-memory machine # [ 32.669392] k3s[877]: I0513 06:00:25.822927 877 event.go:376] "Event occurred" object="kube-system/runtimes" fieldPath="" kind="Addon" apiVersion="k3s.cattle.io/v1" type="Normal" reason="ApplyingManifest" message="Applying manifest at \"/var/lib/rancher/k3s/server/manifests/runtimes.yaml\"" machine # [ 33.235574] k3s[877]: time="2024-05-13T06:00:26Z" level=info msg="Tunnel authorizer set Kubelet Port 10250" machine # [ 33.546184] k3s[877]: I0513 06:00:26.699129 877 serving.go:387] Generated self-signed cert in-memory machine # [ 34.133163] k3s[877]: I0513 06:00:27.286084 877 controllermanager.go:169] Version: v1.29.4+k3s1 machine # [ 34.152565] k3s[877]: time="2024-05-13T06:00:27Z" level=info msg="Stopped tunnel to 127.0.0.1:6443" machine # [ 34.155514] k3s[877]: time="2024-05-13T06:00:27Z" level=info msg="Connecting to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect" machine # [ 34.157395] k3s[877]: time="2024-05-13T06:00:27Z" level=info msg="Proxy done" err="context canceled" url="wss://127.0.0.1:6443/v1-k3s/connect" machine # [ 34.165702] k3s[877]: time="2024-05-13T06:00:27Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF" machine # [ 34.183324] k3s[877]: time="2024-05-13T06:00:27Z" level=info msg="Handling backend connection request [machine]" machine # [ 34.191609] k3s[877]: I0513 06:00:27.345164 877 secure_serving.go:213] Serving securely on 127.0.0.1:10258 machine # [ 34.196325] k3s[877]: I0513 06:00:27.349905 877 requestheader_controller.go:169] Starting RequestHeaderAuthRequestController machine # [ 34.199068] k3s[877]: I0513 06:00:27.352608 877 shared_informer.go:311] Waiting for caches to sync for RequestHeaderAuthRequestController machine # [ 34.202259] k3s[877]: I0513 06:00:27.355840 877 tlsconfig.go:240] "Starting DynamicServingCertificateController" machine # [ 34.205438] k3s[877]: I0513 06:00:27.359023 877 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 34.209128] k3s[877]: I0513 06:00:27.362712 877 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::client-ca-file machine # [ 34.213395] k3s[877]: I0513 06:00:27.366977 877 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 34.216296] k3s[877]: I0513 06:00:27.369882 877 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file machine # [ 34.238475] k3s[877]: time="2024-05-13T06:00:27Z" level=info msg="Remotedialer connected to proxy" url="wss://10.0.2.15:6443/v1-k3s/connect" machine # [ 34.304330] k3s[877]: I0513 06:00:27.457822 877 event.go:376] "Event occurred" object="kube-system/runtimes" fieldPath="" kind="Addon" apiVersion="k3s.cattle.io/v1" type="Normal" reason="AppliedManifest" message="Applied manifest at \"/var/lib/rancher/k3s/server/manifests/runtimes.yaml\"" machine # [ 34.319975] k3s[877]: I0513 06:00:27.473521 877 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::client-ca-file machine # [ 34.325077] k3s[877]: I0513 06:00:27.478552 877 controllermanager.go:338] Started "cloud-node-controller" machine # [ 34.329071] k3s[877]: I0513 06:00:27.481786 877 controllermanager.go:338] Started "cloud-node-lifecycle-controller" machine # [ 34.332167] k3s[877]: W0513 06:00:27.481810 877 controllermanager.go:315] "service-lb-controller" is disabled machine # [ 34.334494] k3s[877]: W0513 06:00:27.481826 877 controllermanager.go:315] "node-route-controller" is disabled machine # [ 34.336308] k3s[877]: I0513 06:00:27.482471 877 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file machine # [ 34.340785] k3s[877]: I0513 06:00:27.482538 877 shared_informer.go:318] Caches are synced for RequestHeaderAuthRequestController machine # [ 34.348924] k3s[877]: I0513 06:00:27.502221 877 node_controller.go:165] Sending events to api server. machine # [ 34.353551] k3s[877]: I0513 06:00:27.507128 877 node_lifecycle_controller.go:113] Sending events to api server machine # [ 34.358264] k3s[877]: I0513 06:00:27.511527 877 node_controller.go:174] Waiting for informer caches to sync machine # [ 34.461890] k3s[877]: I0513 06:00:27.615443 877 node_controller.go:431] Initializing node machine with cloud provider machine # [ 34.692416] k3s[877]: I0513 06:00:27.845935 877 node_controller.go:502] Successfully initialized node machine with cloud provider machine # [ 34.698861] k3s[877]: I0513 06:00:27.852419 877 event.go:376] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="v1" type="Normal" reason="Synced" message="Node synced successfully" machine # [ 36.572428] k3s[877]: I0513 06:00:29.724941 877 serving.go:387] Generated self-signed cert in-memory (finished: must succeed: k3s check-config, in 12.39 seconds) machine: must succeed: /nix/store/4la7iimvg038jv0z5m6jv435x7rn8v6k-stream-pause | ctr image import - machine # [ 37.526693] k3s[877]: I0513 06:00:30.679220 877 server.go:154] "Starting Kubernetes Scheduler" version="v1.29.4+k3s1" machine # [ 37.529506] k3s[877]: I0513 06:00:30.679253 877 server.go:156] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK="" machine # [ 37.552651] k3s[877]: I0513 06:00:30.706124 877 secure_serving.go:213] Serving securely on 127.0.0.1:10259 machine # [ 37.561781] k3s[877]: I0513 06:00:30.714965 877 requestheader_controller.go:169] Starting RequestHeaderAuthRequestController machine # [ 37.564528] k3s[877]: I0513 06:00:30.715314 877 shared_informer.go:311] Waiting for caches to sync for RequestHeaderAuthRequestController machine # [ 37.569358] k3s[877]: I0513 06:00:30.721578 877 tlsconfig.go:240] "Starting DynamicServingCertificateController" machine # [ 37.587253] k3s[877]: I0513 06:00:30.735518 877 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file" machine # [ 37.590079] k3s[877]: I0513 06:00:30.743490 877 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::client-ca-file machine # [ 37.593470] k3s[877]: I0513 06:00:30.743599 877 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" machine # [ 37.597190] k3s[877]: I0513 06:00:30.743618 877 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file machine # [ 37.768928] k3s[877]: I0513 06:00:30.922328 877 shared_informer.go:318] Caches are synced for RequestHeaderAuthRequestController machine # [ 37.792545] k3s[877]: I0513 06:00:30.944765 877 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::client-ca-file machine # [ 37.803097] k3s[877]: I0513 06:00:30.956619 877 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file machine # No 'fromImage' provided machine # Creating layer 1 from paths: ['/nix/store/gm61h1y42pqyl6178g90x8zm22n6pyy5-libunistring-1.1'] machine # Creating layer 2 from paths: ['/nix/store/ddfzjdykw67s20c35i7a6624by3iz5jv-libidn2-2.3.7'] machine # Creating layer 3 from paths: ['/nix/store/nrwkk6ak3rgkrxbqhsscb01jpzmslf2r-xgcc-13.2.0-libgcc'] machine # Creating layer 4 from paths: ['/nix/store/apab5i73dqa09wx0q27b6fbhd1r18ihl-glibc-2.39-31'] machine # [ 41.074243] k3s[877]: I0513 06:00:34.227497 877 range_allocator.go:111] "No Secondary Service CIDR provided. Skipping filtering out secondary service addresses" machine # [ 41.079931] k3s[877]: I0513 06:00:34.230280 877 controllermanager.go:735] "Started controller" controller="node-ipam-controller" machine # [ 41.084155] k3s[877]: I0513 06:00:34.237745 877 node_ipam_controller.go:160] "Starting ipam controller" machine # [ 41.087150] k3s[877]: I0513 06:00:34.240719 877 shared_informer.go:311] Waiting for caches to sync for node machine # [ 41.111485] k3s[877]: I0513 06:00:34.265068 877 controllermanager.go:735] "Started controller" controller="persistentvolume-binder-controller" machine # [ 41.119351] k3s[877]: I0513 06:00:34.272927 877 pv_controller_base.go:319] "Starting persistent volume controller" machine # [ 41.125088] k3s[877]: I0513 06:00:34.275241 877 shared_informer.go:311] Waiting for caches to sync for persistent volume machine # [ 41.147733] k3s[877]: I0513 06:00:34.301269 877 controllermanager.go:735] "Started controller" controller="persistentvolume-attach-detach-controller" machine # [ 41.152528] k3s[877]: I0513 06:00:34.306090 877 attach_detach_controller.go:337] "Starting attach detach controller" machine # [ 41.154934] k3s[877]: I0513 06:00:34.308285 877 shared_informer.go:311] Waiting for caches to sync for attach detach machine # [ 41.178945] k3s[877]: I0513 06:00:34.332525 877 controllermanager.go:735] "Started controller" controller="persistentvolume-protection-controller" machine # [ 41.182606] k3s[877]: I0513 06:00:34.335962 877 pv_protection_controller.go:78] "Starting PV protection controller" machine # [ 41.185336] k3s[877]: I0513 06:00:34.335984 877 shared_informer.go:311] Waiting for caches to sync for PV protection machine # [ 41.209558] k3s[877]: I0513 06:00:34.363141 877 controllermanager.go:735] "Started controller" controller="ttl-after-finished-controller" machine # [ 41.212214] k3s[877]: I0513 06:00:34.365131 877 ttlafterfinished_controller.go:109] "Starting TTL after finished controller" machine # [ 41.214898] k3s[877]: I0513 06:00:34.365147 877 shared_informer.go:311] Waiting for caches to sync for TTL after finished machine # [ 41.244174] k3s[877]: I0513 06:00:34.397737 877 controllermanager.go:735] "Started controller" controller="replicationcontroller-controller" machine # [ 41.251756] k3s[877]: I0513 06:00:34.405345 877 replica_set.go:214] "Starting controller" name="replicationcontroller" machine # [ 41.254173] k3s[877]: I0513 06:00:34.407767 877 shared_informer.go:311] Waiting for caches to sync for ReplicationController machine # [ 41.304103] k3s[877]: I0513 06:00:34.457278 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="roles.rbac.authorization.k8s.io" machine # [ 41.307387] k3s[877]: I0513 06:00:34.457326 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="limitranges" machine # [ 41.309129] k3s[877]: I0513 06:00:34.457361 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="poddisruptionbudgets.policy" machine # [ 41.312114] k3s[877]: I0513 06:00:34.457404 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="endpoints" machine # [ 41.315174] k3s[877]: I0513 06:00:34.457446 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="controllerrevisions.apps" machine # [ 41.318474] k3s[877]: I0513 06:00:34.457484 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="deployments.apps" machine # [ 41.321177] k3s[877]: I0513 06:00:34.457521 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="csistoragecapacities.storage.k8s.io" machine # [ 41.323358] k3s[877]: I0513 06:00:34.457556 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="endpointslices.discovery.k8s.io" machine # [ 41.326807] k3s[877]: W0513 06:00:34.457574 877 shared_informer.go:591] resyncPeriod 13h31m6.250186058s is smaller than resyncCheckPeriod 22h9m41.635985692s and the informer has already started. Changing it to 22h9m41.635985692s machine # [ 41.335343] k3s[877]: I0513 06:00:34.488839 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="networkpolicies.networking.k8s.io" machine # [ 41.340503] k3s[877]: I0513 06:00:34.494011 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="serviceaccounts" machine # [ 41.344146] k3s[877]: I0513 06:00:34.497555 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="cronjobs.batch" machine # [ 41.347467] k3s[877]: I0513 06:00:34.501014 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="ingresses.networking.k8s.io" machine # [ 41.350128] k3s[877]: I0513 06:00:34.503485 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="helmcharts.helm.cattle.io" machine # [ 41.353734] k3s[877]: I0513 06:00:34.507315 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="daemonsets.apps" machine # [ 41.357117] k3s[877]: I0513 06:00:34.510581 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="replicasets.apps" machine # [ 41.362490] k3s[877]: I0513 06:00:34.515996 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="rolebindings.rbac.authorization.k8s.io" machine # [ 41.365906] k3s[877]: I0513 06:00:34.519422 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="leases.coordination.k8s.io" machine # [ 41.370423] k3s[877]: I0513 06:00:34.523907 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="addons.k3s.cattle.io" machine # [ 41.373641] k3s[877]: I0513 06:00:34.527139 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="horizontalpodautoscalers.autoscaling" machine # [ 41.376287] k3s[877]: I0513 06:00:34.529804 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="helmchartconfigs.helm.cattle.io" machine # [ 41.380144] k3s[877]: I0513 06:00:34.533709 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="podtemplates" machine # [ 41.382239] k3s[877]: I0513 06:00:34.535800 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="jobs.batch" machine # [ 41.386178] k3s[877]: I0513 06:00:34.539598 877 resource_quota_monitor.go:224] "QuotaMonitor created object count evaluator" resource="statefulsets.apps" machine # [ 41.391180] k3s[877]: I0513 06:00:34.542846 877 controllermanager.go:735] "Started controller" controller="resourcequota-controller" machine # [ 41.394112] k3s[877]: I0513 06:00:34.543123 877 resource_quota_controller.go:294] "Starting resource quota controller" machine # [ 41.396651] k3s[877]: I0513 06:00:34.543140 877 shared_informer.go:311] Waiting for caches to sync for resource quota machine # [ 41.398259] k3s[877]: I0513 06:00:34.543698 877 resource_quota_monitor.go:305] "QuotaMonitor running" machine # [ 41.443208] k3s[877]: I0513 06:00:34.596000 877 controllermanager.go:735] "Started controller" controller="garbage-collector-controller" machine # [ 41.446688] k3s[877]: I0513 06:00:34.596237 877 garbagecollector.go:155] "Starting controller" controller="garbagecollector" machine # [ 41.448861] k3s[877]: I0513 06:00:34.596253 877 shared_informer.go:311] Waiting for caches to sync for garbage collector machine # [ 41.450232] k3s[877]: I0513 06:00:34.596530 877 graph_builder.go:302] "Running" component="GraphBuilder" machine # [ 41.506660] k3s[877]: I0513 06:00:34.660226 877 controllermanager.go:735] "Started controller" controller="disruption-controller" machine # [ 41.511446] k3s[877]: I0513 06:00:34.665017 877 disruption.go:433] "Sending events to api server." machine # [ 41.514391] k3s[877]: I0513 06:00:34.667868 877 disruption.go:444] "Starting disruption controller" machine # [ 41.517310] k3s[877]: I0513 06:00:34.670797 877 shared_informer.go:311] Waiting for caches to sync for disruption machine # [ 41.538164] k3s[877]: I0513 06:00:34.691725 877 controllermanager.go:735] "Started controller" controller="certificatesigningrequest-signing-controller" machine # [ 41.541816] k3s[877]: I0513 06:00:34.695097 877 controllermanager.go:698] "Warning: controller is disabled" controller="bootstrap-signer-controller" machine # [ 41.544774] k3s[877]: I0513 06:00:34.698282 877 controllermanager.go:687] "Controller is disabled by a feature gate" controller="storageversion-garbage-collector-controller" requiredFeatureGates=["APIServerIdentity","StorageVersionAPI"] machine # [ 41.549060] k3s[877]: I0513 06:00:34.702486 877 certificate_controller.go:115] "Starting certificate controller" name="csrsigning-kubelet-serving" machine # [ 41.552364] k3s[877]: I0513 06:00:34.702506 877 shared_informer.go:311] Waiting for caches to sync for certificate-csrsigning-kubelet-serving machine # [ 41.555477] k3s[877]: I0513 06:00:34.702574 877 certificate_controller.go:115] "Starting certificate controller" name="csrsigning-kubelet-client" machine # [ 41.557314] k3s[877]: I0513 06:00:34.702586 877 shared_informer.go:311] Waiting for caches to sync for certificate-csrsigning-kubelet-client machine # [ 41.559277] k3s[877]: I0513 06:00:34.712870 877 certificate_controller.go:115] "Starting certificate controller" name="csrsigning-kube-apiserver-client" machine # [ 41.561381] k3s[877]: I0513 06:00:34.714963 877 shared_informer.go:311] Waiting for caches to sync for certificate-csrsigning-kube-apiserver-client machine # [ 41.565728] k3s[877]: I0513 06:00:34.719320 877 certificate_controller.go:115] "Starting certificate controller" name="csrsigning-legacy-unknown" machine # [ 41.569621] k3s[877]: I0513 06:00:34.723189 877 shared_informer.go:311] Waiting for caches to sync for certificate-csrsigning-legacy-unknown machine # [ 41.578419] k3s[877]: I0513 06:00:34.731971 877 dynamic_serving_content.go:132] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/server-ca.key" machine # [ 41.586114] k3s[877]: I0513 06:00:34.739228 877 dynamic_serving_content.go:132] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/client-ca.key" machine # [ 41.592403] k3s[877]: I0513 06:00:34.739419 877 dynamic_serving_content.go:132] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/client-ca.key" machine # [ 41.599965] k3s[877]: I0513 06:00:34.749027 877 dynamic_serving_content.go:132] "Starting controller" name="csr-controller::/var/lib/rancher/k3s/server/tls/server-ca.nochain.crt::/var/lib/rancher/k3s/server/tls/server-ca.key" machine # [ 41.638847] k3s[877]: I0513 06:00:34.792209 877 controllermanager.go:735] "Started controller" controller="endpointslice-controller" machine # [ 41.642126] k3s[877]: I0513 06:00:34.795297 877 endpointslice_controller.go:264] "Starting endpoint slice controller" machine # [ 41.643880] k3s[877]: I0513 06:00:34.795321 877 shared_informer.go:311] Waiting for caches to sync for endpoint_slice machine # [ 41.709476] k3s[877]: I0513 06:00:34.862567 877 controllermanager.go:735] "Started controller" controller="serviceaccount-controller" machine # [ 41.711514] k3s[877]: I0513 06:00:34.862757 877 serviceaccounts_controller.go:111] "Starting service account controller" machine # [ 41.713767] k3s[877]: I0513 06:00:34.862776 877 shared_informer.go:311] Waiting for caches to sync for service account machine # [ 41.866077] k3s[877]: I0513 06:00:35.018873 877 controllermanager.go:735] "Started controller" controller="job-controller" machine # [ 41.868693] k3s[877]: I0513 06:00:35.019292 877 job_controller.go:224] "Starting job controller" machine # [ 41.870166] k3s[877]: I0513 06:00:35.019328 877 shared_informer.go:311] Waiting for caches to sync for job machine # [ 42.014176] k3s[877]: I0513 06:00:35.167262 877 controllermanager.go:735] "Started controller" controller="endpoints-controller" machine # [ 42.016355] k3s[877]: I0513 06:00:35.167529 877 endpoints_controller.go:174] "Starting endpoint controller" machine # [ 42.018175] k3s[877]: I0513 06:00:35.167550 877 shared_informer.go:311] Waiting for caches to sync for endpoint machine # [ 42.059153] k3s[877]: I0513 06:00:35.212540 877 controllermanager.go:735] "Started controller" controller="certificatesigningrequest-approving-controller" machine # [ 42.061559] k3s[877]: I0513 06:00:35.212577 877 controllermanager.go:698] "Warning: controller is disabled" controller="node-route-controller" machine # [ 42.065323] k3s[877]: I0513 06:00:35.218584 877 certificate_controller.go:115] "Starting certificate controller" name="csrapproving" machine # [ 42.067544] k3s[877]: I0513 06:00:35.218611 877 shared_informer.go:311] Waiting for caches to sync for certificate-csrapproving machine # [ 42.214217] k3s[877]: I0513 06:00:35.367413 877 controllermanager.go:735] "Started controller" controller="ephemeral-volume-controller" machine # [ 42.217285] k3s[877]: I0513 06:00:35.369824 877 controllermanager.go:687] "Controller is disabled by a feature gate" controller="validatingadmissionpolicy-status-controller" requiredFeatureGates=["ValidatingAdmissionPolicy"] machine # [ 42.220272] k3s[877]: I0513 06:00:35.370107 877 controller.go:169] "Starting ephemeral volume controller" machine # [ 42.221870] k3s[877]: I0513 06:00:35.370129 877 shared_informer.go:311] Waiting for caches to sync for ephemeral machine # [ 42.389599] k3s[877]: I0513 06:00:35.543043 877 controllermanager.go:735] "Started controller" controller="endpointslice-mirroring-controller" machine # [ 42.394375] k3s[877]: I0513 06:00:35.547548 877 endpointslicemirroring_controller.go:223] "Starting EndpointSliceMirroring controller" machine # [ 42.397216] k3s[877]: I0513 06:00:35.547569 877 shared_informer.go:311] Waiting for caches to sync for endpoint_slice_mirroring machine # [ 42.519372] k3s[877]: I0513 06:00:35.672575 877 controllermanager.go:735] "Started controller" controller="daemonset-controller" machine # [ 42.521551] k3s[877]: I0513 06:00:35.675142 877 daemon_controller.go:291] "Starting daemon sets controller" machine # [ 42.524247] k3s[877]: I0513 06:00:35.677828 877 shared_informer.go:311] Waiting for caches to sync for daemon sets machine # [ 42.557096] k3s[877]: I0513 06:00:35.710209 877 controllermanager.go:735] "Started controller" controller="certificatesigningrequest-cleaner-controller" machine # [ 42.559187] k3s[877]: I0513 06:00:35.710243 877 controllermanager.go:698] "Warning: controller is disabled" controller="service-lb-controller" machine # [ 42.561096] k3s[877]: I0513 06:00:35.710260 877 controllermanager.go:698] "Warning: controller is disabled" controller="cloud-node-lifecycle-controller" machine # [ 42.563178] k3s[877]: I0513 06:00:35.710358 877 cleaner.go:83] "Starting CSR cleaner controller" machine # [ 42.712475] k3s[877]: I0513 06:00:35.866043 877 controllermanager.go:735] "Started controller" controller="clusterrole-aggregation-controller" machine # [ 42.715623] k3s[877]: I0513 06:00:35.866244 877 controllermanager.go:687] "Controller is disabled by a feature gate" controller="service-cidr-controller" requiredFeatureGates=["MultiCIDRServiceAllocator"] machine # [ 42.718365] k3s[877]: I0513 06:00:35.866321 877 clusterroleaggregation_controller.go:189] "Starting ClusterRoleAggregator controller" machine # [ 42.720662] k3s[877]: I0513 06:00:35.868764 877 shared_informer.go:311] Waiting for caches to sync for ClusterRoleAggregator machine # [ 42.864215] k3s[877]: I0513 06:00:36.017598 877 controllermanager.go:735] "Started controller" controller="deployment-controller" machine # [ 42.867823] k3s[877]: I0513 06:00:36.021383 877 deployment_controller.go:168] "Starting controller" controller="deployment" machine # [ 42.870164] k3s[877]: I0513 06:00:36.023119 877 shared_informer.go:311] Waiting for caches to sync for deployment machine # [ 43.012148] k3s[877]: I0513 06:00:36.165565 877 controllermanager.go:735] "Started controller" controller="replicaset-controller" machine # [ 43.015152] k3s[877]: I0513 06:00:36.168523 877 replica_set.go:214] "Starting controller" name="replicaset" machine # [ 43.017268] k3s[877]: I0513 06:00:36.168544 877 shared_informer.go:311] Waiting for caches to sync for ReplicaSet machine # [ 43.163593] k3s[877]: I0513 06:00:36.316402 877 controllermanager.go:735] "Started controller" controller="cronjob-controller" machine # [ 43.166172] k3s[877]: I0513 06:00:36.319083 877 cronjob_controllerv2.go:139] "Starting cronjob controller v2" machine # [ 43.167677] k3s[877]: I0513 06:00:36.319103 877 shared_informer.go:311] Waiting for caches to sync for cronjob machine # [ 43.313885] k3s[877]: I0513 06:00:36.466881 877 controllermanager.go:735] "Started controller" controller="legacy-serviceaccount-token-cleaner-controller" machine # [ 43.316754] k3s[877]: I0513 06:00:36.467087 877 legacy_serviceaccount_token_cleaner.go:103] "Starting legacy service account token cleaner controller" machine # [ 43.318926] k3s[877]: I0513 06:00:36.467105 877 shared_informer.go:311] Waiting for caches to sync for legacy-service-account-token-cleaner machine # [ 43.458116] k3s[877]: I0513 06:00:36.611176 877 controllermanager.go:735] "Started controller" controller="token-cleaner-controller" machine # [ 43.461411] k3s[877]: I0513 06:00:36.611276 877 tokencleaner.go:112] "Starting token cleaner controller" machine # [ 43.463302] k3s[877]: I0513 06:00:36.611292 877 shared_informer.go:311] Waiting for caches to sync for token_cleaner machine # [ 43.465326] k3s[877]: I0513 06:00:36.611305 877 shared_informer.go:318] Caches are synced for token_cleaner machine # [ 43.613224] k3s[877]: I0513 06:00:36.766209 877 controllermanager.go:735] "Started controller" controller="persistentvolume-expander-controller" machine # [ 43.616366] k3s[877]: I0513 06:00:36.766349 877 expand_controller.go:328] "Starting expand controller" machine # [ 43.617636] k3s[877]: I0513 06:00:36.766365 877 shared_informer.go:311] Waiting for caches to sync for expand machine # [ 43.756741] k3s[877]: I0513 06:00:36.910248 877 controllermanager.go:735] "Started controller" controller="root-ca-certificate-publisher-controller" machine # [ 43.760361] k3s[877]: I0513 06:00:36.913950 877 publisher.go:102] "Starting root CA cert publisher controller" machine # [ 43.762084] k3s[877]: I0513 06:00:36.915677 877 shared_informer.go:311] Waiting for caches to sync for crt configmap machine # [ 43.907648] k3s[877]: I0513 06:00:37.061213 877 controllermanager.go:735] "Started controller" controller="pod-garbage-collector-controller" machine # [ 43.912684] k3s[877]: I0513 06:00:37.066237 877 gc_controller.go:101] "Starting GC controller" machine # [ 43.914549] k3s[877]: I0513 06:00:37.067611 877 shared_informer.go:311] Waiting for caches to sync for GC machine # [ 44.173268] k3s[877]: I0513 06:00:37.326772 877 controllermanager.go:735] "Started controller" controller="namespace-controller" machine # [ 44.175827] k3s[877]: I0513 06:00:37.329090 877 namespace_controller.go:197] "Starting namespace controller" machine # [ 44.177378] k3s[877]: I0513 06:00:37.329112 877 shared_informer.go:311] Waiting for caches to sync for namespace machine # [ 44.311210] k3s[877]: I0513 06:00:37.464482 877 controllermanager.go:735] "Started controller" controller="ttl-controller" machine # [ 44.320154] k3s[877]: I0513 06:00:37.473373 877 ttl_controller.go:124] "Starting TTL controller" machine # [ 44.322141] k3s[877]: I0513 06:00:37.475400 877 shared_informer.go:311] Waiting for caches to sync for TTL machine # [ 44.345517] k3s[877]: I0513 06:00:37.499101 877 shared_informer.go:311] Waiting for caches to sync for resource quota machine # [ 44.449631] k3s[877]: I0513 06:00:37.603063 877 shared_informer.go:318] Caches are synced for certificate-csrsigning-kubelet-client machine # [ 44.457332] k3s[877]: I0513 06:00:37.610770 877 shared_informer.go:318] Caches are synced for ReplicationController machine # [ 44.461494] k3s[877]: I0513 06:00:37.615035 877 shared_informer.go:318] Caches are synced for HPA machine # [ 44.465567] k3s[877]: I0513 06:00:37.619159 877 shared_informer.go:318] Caches are synced for cronjob machine # [ 44.467523] k3s[877]: I0513 06:00:37.621116 877 shared_informer.go:318] Caches are synced for job machine # [ 44.470434] k3s[877]: I0513 06:00:37.624016 877 shared_informer.go:318] Caches are synced for deployment machine # [ 44.473194] k3s[877]: I0513 06:00:37.625853 877 actual_state_of_world.go:547] "Failed to update statusUpdateNeeded field in actual state of world" err="Failed to set statusUpdateNeeded to needed true, because nodeName=\"machine\" does not exist" machine # [ 44.476768] k3s[877]: I0513 06:00:37.626255 877 shared_informer.go:318] Caches are synced for certificate-csrsigning-kubelet-serving machine # [ 44.483475] k3s[877]: I0513 06:00:37.637037 877 shared_informer.go:318] Caches are synced for PV protection machine # [ 44.486336] k3s[877]: I0513 06:00:37.639911 877 shared_informer.go:318] Caches are synced for certificate-csrsigning-kube-apiserver-client machine # [ 44.489748] k3s[877]: I0513 06:00:37.643031 877 shared_informer.go:318] Caches are synced for node machine # [ 44.494235] k3s[877]: I0513 06:00:37.647824 877 shared_informer.go:318] Caches are synced for endpoint_slice_mirroring machine # [ 44.497168] k3s[877]: I0513 06:00:37.649744 877 shared_informer.go:318] Caches are synced for certificate-csrsigning-legacy-unknown machine # [ 44.512518] k3s[877]: I0513 06:00:37.666093 877 shared_informer.go:318] Caches are synced for TTL after finished machine # [ 44.514439] k3s[877]: I0513 06:00:37.668032 877 shared_informer.go:318] Caches are synced for GC machine # [ 44.520752] k3s[877]: I0513 06:00:37.674260 877 shared_informer.go:318] Caches are synced for disruption machine # [ 44.528115] k3s[877]: I0513 06:00:37.680928 877 shared_informer.go:318] Caches are synced for daemon sets machine # [ 44.533547] k3s[877]: I0513 06:00:37.681136 877 shared_informer.go:318] Caches are synced for certificate-csrapproving machine # [ 44.535455] k3s[877]: I0513 06:00:37.681536 877 shared_informer.go:318] Caches are synced for taint machine # [ 44.537565] k3s[877]: I0513 06:00:37.681627 877 node_lifecycle_controller.go:1222] "Initializing eviction metric for zone" zone="" machine # [ 44.541109] k3s[877]: I0513 06:00:37.694694 877 shared_informer.go:318] Caches are synced for TTL machine # [ 44.552201] k3s[877]: I0513 06:00:37.705720 877 shared_informer.go:318] Caches are synced for taint-eviction-controller machine # [ 44.555117] k3s[877]: I0513 06:00:37.707819 877 range_allocator.go:174] "Sending events to api server" machine # [ 44.556619] k3s[877]: I0513 06:00:37.707861 877 range_allocator.go:178] "Starting range CIDR allocator" machine # [ 44.558143] k3s[877]: I0513 06:00:37.707874 877 shared_informer.go:311] Waiting for caches to sync for cidrallocator machine # [ 44.559791] k3s[877]: I0513 06:00:37.707888 877 shared_informer.go:318] Caches are synced for cidrallocator machine # [ 44.564150] k3s[877]: I0513 06:00:37.717665 877 shared_informer.go:318] Caches are synced for legacy-service-account-token-cleaner machine # [ 44.568182] k3s[877]: I0513 06:00:37.721217 877 shared_informer.go:318] Caches are synced for endpoint machine # [ 44.570173] k3s[877]: I0513 06:00:37.721614 877 shared_informer.go:318] Caches are synced for ReplicaSet machine # [ 44.577752] k3s[877]: I0513 06:00:37.730795 877 node_lifecycle_controller.go:874] "Missing timestamp for Node. Assuming now as a timestamp" node="machine" machine # [ 44.579675] k3s[877]: I0513 06:00:37.730892 877 node_lifecycle_controller.go:1068] "Controller detected that zone is now in new state" zone="" newState="Normal" machine # [ 44.583129] k3s[877]: I0513 06:00:37.736478 877 shared_informer.go:318] Caches are synced for endpoint_slice machine # [ 44.593700] k3s[877]: I0513 06:00:37.747264 877 event.go:376] "Event occurred" object="machine" fieldPath="" kind="Node" apiVersion="v1" type="Normal" reason="RegisteredNode" message="Node machine event: Registered Node machine in Controller" machine # [ 44.597208] k3s[877]: I0513 06:00:37.750318 877 shared_informer.go:318] Caches are synced for crt configmap machine # Creating layer 5 from paths: ['/nix/store/yb39i0a63bx8kx2bgmx1p4dx1hcwmnzh-attr-2.5.2'] machine # [ 44.608069] k3s[877]: I0513 06:00:37.761379 877 shared_informer.go:318] Caches are synced for namespace machine # [ 44.610199] k3s[877]: I0513 06:00:37.763078 877 shared_informer.go:318] Caches are synced for service account machine # [ 44.718574] k3s[877]: I0513 06:00:37.870630 877 shared_informer.go:318] Caches are synced for ephemeral machine # [ 44.723515] k3s[877]: I0513 06:00:37.877102 877 shared_informer.go:318] Caches are synced for ClusterRoleAggregator machine # [ 44.729671] k3s[877]: I0513 06:00:37.883265 877 shared_informer.go:318] Caches are synced for persistent volume machine # [ 44.743655] k3s[877]: I0513 06:00:37.897054 877 shared_informer.go:318] Caches are synced for resource quota machine # [ 44.748402] k3s[877]: I0513 06:00:37.901746 877 shared_informer.go:318] Caches are synced for PVC protection machine # [ 44.757085] k3s[877]: I0513 06:00:37.910183 877 shared_informer.go:318] Caches are synced for stateful set machine # [ 44.760942] k3s[877]: I0513 06:00:37.914527 877 shared_informer.go:318] Caches are synced for attach detach machine # [ 44.768930] k3s[877]: I0513 06:00:37.917593 877 shared_informer.go:311] Waiting for caches to sync for garbage collector machine # [ 44.789700] k3s[877]: I0513 06:00:37.943269 877 shared_informer.go:318] Caches are synced for resource quota machine # [ 44.796510] k3s[877]: I0513 06:00:37.949938 877 range_allocator.go:380] "Set node PodCIDR" node="machine" podCIDRs=["10.42.0.0/24"] machine # [ 44.814098] k3s[877]: I0513 06:00:37.967630 877 shared_informer.go:318] Caches are synced for expand machine # [ 44.840109] k3s[877]: time="2024-05-13T06:00:37Z" level=info msg="Flannel found PodCIDR assigned for node machine" machine # [ 44.861612] k3s[877]: time="2024-05-13T06:00:38Z" level=info msg="The interface eth0 with ipv4 address 10.0.2.15 will be used by flannel" machine # [ 44.886108] k3s[877]: I0513 06:00:38.039603 877 kube.go:139] Waiting 10m0s for node controller to sync machine # [ 44.907372] k3s[877]: I0513 06:00:38.060267 877 kube.go:461] Starting kube subnet manager machine # Creating layer 6 from paths: ['/nix/store/k927dryij6k8ga8slxs39pjdsmsny8c8-gcc-13.2.0-libgcc'] machine # Creating layer 7 from paths: ['/nix/store/p3ffjixpnfgkqh20nsrc13vrj3yfi0nj-gcc-13.2.0-lib'] machine # [ 45.145396] k3s[877]: I0513 06:00:38.298610 877 shared_informer.go:318] Caches are synced for garbage collector machine # [ 45.148253] k3s[877]: I0513 06:00:38.298828 877 garbagecollector.go:166] "All resource monitors have synced. Proceeding to collect garbage" machine # [ 45.164730] k3s[877]: I0513 06:00:38.318029 877 shared_informer.go:318] Caches are synced for garbage collector machine # [ 45.336174] k3s[877]: time="2024-05-13T06:00:38Z" level=info msg="Starting network policy controller version , built on , go1.21.10" machine # [ 45.339322] k3s[877]: I0513 06:00:38.488990 877 network_policy_controller.go:164] Starting network policy controller machine # [ 45.466261] k3s[877]: I0513 06:00:38.619166 877 kuberuntime_manager.go:1529] "Updating runtime config through cri with podcidr" CIDR="10.42.0.0/24" machine # [ 45.536629] k3s[877]: I0513 06:00:38.690175 877 kubelet_network.go:61] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="10.42.0.0/24" machine # Creating layer 8 from paths: ['/nix/store/y4psv76i8pllhnsd1dg7zbqsj8a2sz64-acl-2.3.2'] machine # [ 45.921206] k3s[877]: I0513 06:00:39.074091 877 kube.go:146] Node controller sync successful machine # [ 45.924325] k3s[877]: I0513 06:00:39.074182 877 vxlan.go:141] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false machine # [ 45.981369] k3s[877]: I0513 06:00:39.134882 877 kube.go:621] List of node(machine) annotations: map[string]string{"alpha.kubernetes.io/provided-node-ip":"10.0.2.15,fec0::1620:efe5:3e6d:8a9", "k3s.io/hostname":"machine", "k3s.io/internal-ip":"10.0.2.15,fec0::1620:efe5:3e6d:8a9", "k3s.io/node-args":"[\"server\",\"--disable\",\"coredns\",\"--disable\",\"local-storage\",\"--disable\",\"metrics-server\",\"--disable\",\"servicelb\",\"--disable\",\"traefik\",\"--pause-image\",\"test.local/pause:local\"]", "k3s.io/node-config-hash":"N5CWQS5FSIFEDNFNLWW6VL4VHYTKLCEAZMYBE5Q3PSEHY6FMV4GA====", "k3s.io/node-env":"{\"K3S_DATA_DIR\":\"/var/lib/rancher/k3s/data/3e385e46fcffb163f336e2c55162854c8577cca4831e39e920cc7efcc160284c\"}", "node.alpha.kubernetes.io/ttl":"0", "volumes.kubernetes.io/controller-managed-attach-detach":"true"} machine # [ 46.119777] (udev-worker)[2387]: Network interface NamePolicy= disabled on kernel command line. machine # [ 46.232089] k3s[877]: I0513 06:00:39.385267 877 kube.go:482] Creating the node lease for IPv4. This is the n.Spec.PodCIDRs: [10.42.0.0/24] machine # Creating layer 9 from paths: ['/nix/store/5gzyfqc5vzm4gyijkyxw8bl8i91zfk77-gmp-with-cxx-6.3.0'] machine # [ 46.275788] k3s[877]: I0513 06:00:39.429148 877 network_policy_controller.go:176] Starting network policy controller full sync goroutine machine # [ 46.287869] dhcpcd[668]: flannel.1: waiting for carrier machine # [ 46.289723] dhcpcd[668]: flannel.1: carrier acquired machine # [ 46.327768] dhcpcd[668]: flannel.1: IAID b3:57:a4:5e machine # [ 46.328863] dhcpcd[668]: flannel.1: adding address fe80::74b0:b3ff:fe57:a45e machine # Creating layer 10 from paths: ['/nix/store/mpikxgafqrrdxmmmsb8c813gdng4db5r-busybox-1.36.1'] machine # [ 46.375782] k3s[877]: time="2024-05-13T06:00:39Z" level=info msg="Wrote flannel subnet file to /run/flannel/subnet.env" machine # [ 46.379643] k3s[877]: time="2024-05-13T06:00:39Z" level=info msg="Running flannel backend." machine # [ 46.381240] k3s[877]: I0513 06:00:39.528532 877 vxlan_network.go:65] watching for new subnet leases machine # [ 46.383637] k3s[877]: I0513 06:00:39.532124 877 iptables.go:290] generated 3 rules machine # [ 46.407398] k3s[877]: I0513 06:00:39.560945 877 iptables.go:290] generated 7 rules machine # [ 46.662864] k3s[877]: I0513 06:00:39.816348 877 iptables.go:283] bootstrap done machine # [ 46.845916] dhcpcd[668]: flannel.1: soliciting an IPv6 router machine # [ 46.889186] k3s[877]: I0513 06:00:40.042196 877 iptables.go:283] bootstrap done machine # [ 47.218877] dhcpcd[668]: flannel.1: soliciting a DHCP lease machine # Creating layer 11 from paths: ['/nix/store/ddypgcb25zgi0gwvklxlzazjrh9s63dg-coreutils-9.5'] machine # Creating layer 12 from paths: ['/nix/store/pv1qqznnjw7473h0h95qpdm3f3z4rfcf-tini-0.19.0'] machine # Creating layer 13 with customisation... machine # Adding manifests... machine # Done. machine # [ 48.081187] systemd[1]: var-lib-rancher-k3s-agent-containerd-tmpmounts-containerd\x2dmount926342089.mount: Deactivated successfully. (finished: must succeed: /nix/store/4la7iimvg038jv0z5m6jv435x7rn8v6k-stream-pause | ctr image import -, in 11.27 seconds) machine: waiting for success: kubectl get serviceaccount default (finished: waiting for success: kubectl get serviceaccount default, in 0.26 seconds) machine: must succeed: kubectl apply -f /nix/store/kpjf4vk3hfdr8gs9lwpwb883ps3rk3zq-test.yml machine # [ 49.442354] k3s[877]: I0513 06:00:42.594371 877 topology_manager.go:215] "Topology Admit Handler" podUID="0ca4595e-3d1f-4d7d-b187-adf7b434a321" podNamespace="default" podName="test" (finished: must succeed: kubectl apply -f /nix/store/kpjf4vk3hfdr8gs9lwpwb883ps3rk3zq-test.yml, in 0.41 seconds) machine: must succeed: kubectl wait --for 'condition=Ready' pod/test machine # [ 49.501619] systemd[1]: Created slice libcontainer container kubepods-besteffort-pod0ca4595e_3d1f_4d7d_b187_adf7b434a321.slice. machine # [ 49.566617] k3s[877]: I0513 06:00:42.720179 877 reconciler_common.go:258] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-7r5gz\" (UniqueName: \"kubernetes.io/projected/0ca4595e-3d1f-4d7d-b187-adf7b434a321-kube-api-access-7r5gz\") pod \"test\" (UID: \"0ca4595e-3d1f-4d7d-b187-adf7b434a321\") " pod="default/test" machine # [ 50.219821] cni0: port 1(veth26d371fb) entered blocking state machine # [ 50.220466] cni0: port 1(veth26d371fb) entered disabled state machine # [ 50.222763] veth26d371fb: entered allmulticast mode machine # [ 50.224927] veth26d371fb: entered promiscuous mode machine # [ 50.250890] cni0: port 1(veth26d371fb) entered blocking state machine # [ 50.251573] cni0: port 1(veth26d371fb) entered forwarding state machine # [ 50.143863] (udev-worker)[2570]: Network interface NamePolicy= disabled on kernel command line. machine # [ 50.148962] (udev-worker)[2572]: Network interface NamePolicy= disabled on kernel command line. machine # [ 50.218270] dhcpcd[668]: veth26d371fb: IAID bb:60:9d:1a machine # [ 50.219578] dhcpcd[668]: veth26d371fb: adding address fe80::a45f:bbff:fe60:9d1a machine # [ 50.555774] systemd[1]: Started libcontainer container f88b85272dcbff6466745c3c2edbe8f2872e85624bbefe00a4113e75f76f6ae3. machine # [ 50.622634] dhcpcd[668]: veth26d371fb: soliciting a DHCP lease machine # [ 50.781333] systemd[1]: Started libcontainer container 1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee. (finished: must succeed: kubectl wait --for 'condition=Ready' pod/test, in 1.42 seconds) machine: must succeed: kubectl delete -f /nix/store/kpjf4vk3hfdr8gs9lwpwb883ps3rk3zq-test.yml machine # [ 50.952358] dhcpcd[668]: veth26d371fb: soliciting an IPv6 router machine # [ 51.234417] k3s[877]: I0513 06:00:44.386738 877 pod_startup_latency_tracker.go:102] "Observed pod startup duration" pod="default/test" podStartSLOduration=2.386612259 podStartE2EDuration="2.386612259s" podCreationTimestamp="2024-05-13 06:00:42 +0000 UTC" firstStartedPulling="0001-01-01 00:00:00 +0000 UTC" lastFinishedPulling="0001-01-01 00:00:00 +0000 UTC" observedRunningTime="2024-05-13 06:00:44.057153068 +0000 UTC m=+34.562544957" watchObservedRunningTime="2024-05-13 06:00:44.386612259 +0000 UTC m=+34.891879831" machine # [ 60.260469] dhcpcd[668]: flannel.1: no IPv6 Routers available machine # [ 63.584083] dhcpcd[668]: veth26d371fb: no IPv6 Routers available machine # [ 81.943692] systemd[1]: cri-containerd-1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee.scope: Deactivated successfully. machine # [ 82.021701] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee-rootfs.mount: Deactivated successfully. machine # [ 82.103903] systemd[1]: run-k3s-containerd-io.containerd.grpc.v1.cri-sandboxes-f88b85272dcbff6466745c3c2edbe8f2872e85624bbefe00a4113e75f76f6ae3-shm.mount: Deactivated successfully. machine # [ 82.148733] systemd[1]: cri-containerd-f88b85272dcbff6466745c3c2edbe8f2872e85624bbefe00a4113e75f76f6ae3.scope: Deactivated successfully. machine # [ 82.245825] systemd[1]: run-k3s-containerd-io.containerd.runtime.v2.task-k8s.io-f88b85272dcbff6466745c3c2edbe8f2872e85624bbefe00a4113e75f76f6ae3-rootfs.mount: Deactivated successfully. machine # [ 82.508493] cni0: port 1(veth26d371fb) entered disabled state machine # [ 82.356548] dhcpcd[668]: veth26d371fb: carrier lost machine # [ 82.512558] veth26d371fb (unregistering): left allmulticast mode machine # [ 82.514020] veth26d371fb (unregistering): left promiscuous mode machine # [ 82.515242] cni0: port 1(veth26d371fb) entered disabled state machine # [ 82.392986] systemd[1]: run-netns-cni\x2d4c9aa5f2\x2de4eb\x2d10c6\x2d86d9\x2d96e3e951455c.mount: Deactivated successfully. machine # [ 82.442277] dhcpcd[668]: ps_bpf_recvbpf: unexpected event 0x0100 machine # [ 82.444554] dhcpcd[668]: veth26d371fb: deleting address fe80::a45f:bbff:fe60:9d1a machine # [ 82.528990] dhcpcd[668]: veth26d371fb: removing interface machine # [ 82.552333] k3s[877]: I0513 06:01:15.704765 877 reconciler_common.go:172] "operationExecutor.UnmountVolume started for volume \"kube-api-access-7r5gz\" (UniqueName: \"kubernetes.io/projected/0ca4595e-3d1f-4d7d-b187-adf7b434a321-kube-api-access-7r5gz\") pod \"0ca4595e-3d1f-4d7d-b187-adf7b434a321\" (UID: \"0ca4595e-3d1f-4d7d-b187-adf7b434a321\") " machine # [ 82.577046] systemd[1]: var-lib-kubelet-pods-0ca4595e\x2d3d1f\x2d4d7d\x2db187\x2dadf7b434a321-volumes-kubernetes.io\x7eprojected-kube\x2dapi\x2daccess\x2d7r5gz.mount: Deactivated successfully. machine # [ 82.584093] k3s[877]: I0513 06:01:15.737553 877 operation_generator.go:887] UnmountVolume.TearDown succeeded for volume "kubernetes.io/projected/0ca4595e-3d1f-4d7d-b187-adf7b434a321-kube-api-access-7r5gz" (OuterVolumeSpecName: "kube-api-access-7r5gz") pod "0ca4595e-3d1f-4d7d-b187-adf7b434a321" (UID: "0ca4595e-3d1f-4d7d-b187-adf7b434a321"). InnerVolumeSpecName "kube-api-access-7r5gz". PluginName "kubernetes.io/projected", VolumeGidValue "" machine # [ 82.652147] k3s[877]: I0513 06:01:15.805702 877 reconciler_common.go:300] "Volume detached for volume \"kube-api-access-7r5gz\" (UniqueName: \"kubernetes.io/projected/0ca4595e-3d1f-4d7d-b187-adf7b434a321-kube-api-access-7r5gz\") on node \"machine\" DevicePath \"\"" machine # [ 82.935980] k3s[877]: I0513 06:01:16.089479 877 scope.go:117] "RemoveContainer" containerID="1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee" machine # [ 82.955973] systemd[1]: Removed slice libcontainer container kubepods-besteffort-pod0ca4595e_3d1f_4d7d_b187_adf7b434a321.slice. machine # [ 82.973758] k3s[877]: I0513 06:01:16.127333 877 scope.go:117] "RemoveContainer" containerID="1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee" machine # [ 82.985059] k3s[877]: E0513 06:01:16.138588 877 remote_runtime.go:432] "ContainerStatus from runtime service failed" err="rpc error: code = NotFound desc = an error occurred when try to find container \"1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee\": not found" containerID="1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee" machine # [ 82.990979] k3s[877]: I0513 06:01:16.144533 877 pod_container_deletor.go:53] "DeleteContainer returned error" containerID={"Type":"containerd","ID":"1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee"} err="failed to get container status \"1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee\": rpc error: code = NotFound desc = an error occurred when try to find container \"1f0ec9c46f6af3ecb7e513d348f49c1654dd0da31ea42b01de2e4e6a3117d3ee\": not found" (finished: must succeed: kubectl delete -f /nix/store/kpjf4vk3hfdr8gs9lwpwb883ps3rk3zq-test.yml, in 32.20 seconds) machine: must fail: journalctl -o cat -u k3s.service | grep 'ipset utility not found' (finished: must fail: journalctl -o cat -u k3s.service | grep 'ipset utility not found', in 0.14 seconds) subtest: Run k3s-killall machine: must succeed: PATH= /nix/store/nd4dvfqsld4v27xfs9ap29ak927nwdwc-k3s-1.29.4+k3s1/bin/k3s-killall.sh 2>&1 | tee /dev/stderr machine # + for service in /etc/systemd/system/k3s*.service machine # + '[' -s /etc/systemd/system/k3s.service ']' machine # ++ basename /etc/systemd/system/k3s.service machine # + systemctl stop k3s.service machine # [ 83.405251] systemd[1]: Stopping k3s service... machine # [ 83.406832] k3s[877]: time="2024-05-13T06:01:16Z" level=info msg="TTL events watch channel closed" machine # [ 83.429047] k3s[877]: I0513 06:01:16.582520 877 secure_serving.go:258] Stopped listening on 127.0.0.1:10259 machine # [ 83.433346] k3s[877]: I0513 06:01:16.585110 877 tlsconfig.go:255] "Shutting down DynamicServingCertificateController" machine # [ 83.435421] k3s[877]: I0513 06:01:16.585605 877 health_controller.go:224] Shutting down HealthController RunCheck machine # [ 83.448443] k3s[877]: E0513 06:01:16.602034 877 subnet.go:145] could not watch leases: context canceled machine # [ 83.450314] k3s[877]: I0513 06:01:16.603860 877 network_policy_controller.go:205] Shutting down network policies controller machine # [ 83.546719] systemd[1]: k3s.service: Deactivated successfully. machine # [ 83.549675] systemd[1]: Stopped k3s service. machine # [ 83.553040] systemd[1]: k3s.service: Consumed 19.796s CPU time, 642.3M memory peak, 0B memory swap peak, read 0B from disk, written 304.0M to disk, received 2.8M IP traffic, sent 4.2M IP traffic. machine # + for service in /etc/init.d/k3s* machine # + '[' -x '/etc/init.d/k3s*' ']' machine # + killtree 2875 machine # + kill -9 2875 machine # + do_unmount_and_remove /run/k3s machine # + set +x machine # + do_unmount_and_remove /var/lib/rancher/k3s machine # + set +x machine # + do_unmount_and_remove /var/lib/kubelet/pods machine # + set +x machine # + do_unmount_and_remove /var/lib/kubelet/plugins machine # + set +x machine # + do_unmount_and_remove /run/netns/cni- machine # + set +x machine # + ip netns show machine # + grep cni- machine # + xargs -r -t -n 1 ip netns delete machine # + remove_interfaces machine # + ip link show machine # + grep 'master cni0' machine # + read ignore iface ignore machine # + ip link delete cni0 machine # + ip link delete flannel.1 machine # [ 83.825709] dhcpcd[668]: flannel.1: carrier lost machine # + ip link delete flannel-v6.1 machine # Cannot find device "flannel-v6.1" machine # [ 83.909752] dhcpcd[668]: ps_bpf_recvbpf: unexpected event 0x0100 machine # + ip link delete kube-ipvs0 machine # [ 83.916509] dhcpcd[668]: flannel.1: deleting address fe80::74b0:b3ff:fe57:a45e machine # Cannot find device "kube-ipvs0" machine # [ 84.001206] dhcpcd[668]: flannel.1: removing interface machine # + ip link delete flannel-wg machine # Cannot find device "flannel-wg" machine # + ip link delete flannel-wg-v6 machine # Cannot find device "flannel-wg-v6" machine # ++ command -v tailscale machine # + '[' -n '' ']' machine # + rm -rf /var/lib/cni/ machine # + iptables-save machine # + grep -v KUBE- machine # + grep -v CNI- machine # + grep -iv flannel machine # + iptables-restore machine # + ip6tables-save machine # + grep -v KUBE- machine # + grep -v CNI- machine # + grep -iv flannel machine # + ip6tables-restore machine # [ 84.445210] hrtimer: interrupt took 4790832 ns (finished: must succeed: PATH= /nix/store/nd4dvfqsld4v27xfs9ap29ak927nwdwc-k3s-1.29.4+k3s1/bin/k3s-killall.sh 2>&1 | tee /dev/stderr, in 1.13 seconds) machine: must fail: systemctl is-active k3s.service (finished: must fail: systemctl is-active k3s.service, in 0.06 seconds) machine: must fail: systemctl list-units | grep containerd (finished: must fail: systemctl list-units | grep containerd, in 0.07 seconds) machine: must fail: ip link show | awk -F': ' '{print $2}' | grep -e flannel -e cni0 (finished: must fail: ip link show | awk -F': ' '{print $2}' | grep -e flannel -e cni0, in 0.06 seconds) machine: must fail: ip netns show | grep cni- (finished: must fail: ip netns show | grep cni-, in 0.04 seconds) (finished: subtest: Run k3s-killall, in 1.35 seconds) machine: waiting for the VM to power off machine # [ 84.605617] systemd-logind[687]: The system will power off now! machine # [ 84.611366] systemd-logind[687]: System is powering down. machine # [ 84.639619] systemd[1]: Removed slice Slice /system/modprobe. machine # [ 84.643956] systemd[1]: Removed slice libcontainer container kubepods-besteffort.slice. machine # [ 84.647233] systemd[1]: Removed slice libcontainer container kubepods-burstable.slice. machine # [ 84.653458] systemd[1]: Removed slice libcontainer container kubepods.slice. machine # [ 84.654846] systemd[1]: Stopped target Multi-User System. machine # [ 84.656246] systemd[1]: Stopped target Login Prompts. machine # [ 84.657504] systemd[1]: Stopped target Containers. machine # [ 84.659057] systemd[1]: Stopped target Network is Online. machine # [ 84.660375] systemd[1]: Stopped target Host and Network Name Lookups. machine # [ 84.662886] systemd[1]: Stopped target Timer Units. machine # [ 84.664436] systemd[1]: systemd-tmpfiles-clean.timer: Deactivated successfully. machine # [ 84.667899] systemd[1]: Stopped Daily Cleanup of Temporary Directories. machine # [ 84.669548] systemd[1]: systemd-rfkill.socket: Deactivated successfully. machine # [ 84.670818] systemd[1]: Closed Load/Save RF Kill Switch Status /dev/rfkill Watch. machine # [ 84.673517] systemd[1]: Mounting /run/initramfs... machine # [ 84.678264] systemd[1]: Stopping Kernel Auditing... machine # [ 84.683129] dhcpcd[668]: received SIGTERM, stopping machine # [ 84.684559] systemd[1]: Stopping backdoor.service... machine # [ 84.687774] dhcpcd[668]: eth0: removing interface machine # [ 84.690194] systemd[1]: Stopping D-Bus System Message Bus... machine # [ 84.698265] dhcpcd[668]: eth0: deleting address fec0::5054:ff:fe12:3456/64 machine # [ 84.712484] systemd[1]: Stopping DHCP Client... machine # [ 84.829673] dhcpcd[668]: eth0: deleting route to fec0::/64 machine # [ 84.843030] systemd[1]: Stopping Getty on tty1... machine # [ 84.856826] dhcpcd[668]: eth0: deleting default route via fe80::2 machine # [ 84.866820] systemd[1]: mount-pstore.service: Deactivated successfully. machine # [ 84.873912] systemd[1]: Stopped mount-pstore.service. machine # [ 84.885216] systemd[1]: reload-systemd-vconsole-setup.service: Deactivated successfully. machine # [ 84.895149] systemd[1]: Stopped Reset console on configuration changes. machine # [ 84.896570] systemd[1]: Starting Save Hardware Clock... machine # [ 84.898298] systemd[1]: Stopping User Login Management... machine # [ 84.899651] systemd[1]: Stopping Userspace Out-Of-Memory (OOM) Killer... machine # [ 84.900688] systemd[1]: Stopping Load/Save OS Random Seed... machine # [ 84.901677] systemd[1]: backdoor.service: Deactivated successfully. machine # [ 84.904047] systemd[1]: Stopped backdoor.service. machine # [ 84.904884] systemd[1]: backdoor.service: Consumed 7.078s CPU time, received 1.4M IP traffic, sent 19.9K IP traffic. machine # [ 84.906494] systemd[1]: dbus.service: Deactivated successfully. machine # [ 84.910201] systemd[1]: Stopped D-Bus System Message Bus. machine # [ 84.911213] systemd[1]: getty@tty1.service: Deactivated successfully. machine # [ 84.912230] systemd[1]: Stopped Getty on tty1. machine # [ 84.929060] systemd[1]: Removed slice Slice /system/getty. machine # [ 84.936686] systemd[1]: Stopping Permit User Sessions... machine # [ 84.950464] systemd[1]: systemd-oomd.service: Deactivated successfully. machine # [ 84.953462] systemd[1]: Stopped Userspace Out-Of-Memory (OOM) Killer. machine # [ 84.966330] systemd[1]: Mounted /run/initramfs. machine # [ 84.971371] systemd[1]: Starting Generate shutdown ramfs... machine # [ 84.974972] systemd[1]: systemd-logind.service: Deactivated successfully. machine # [ 84.982185] systemd[1]: Stopped User Login Management. machine # [ 85.022299] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2991]: No rules machine # [ 85.031982] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: enabled 0 machine # [ 85.035099] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: failure 1 machine # [ 85.038134] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: pid 0 machine # [ 85.039454] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: rate_limit 0 machine # [ 85.042865] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: backlog_limit 64 machine # [ 85.044397] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: lost 0 machine # [ 85.045522] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: backlog 0 machine # [ 85.053732] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: backlog_wait_time 60000 machine # [ 85.055087] zr090ikr8vcf91z3jj27f9gczzm2q8c9-audit-stop[2994]: backlog_wait_time_actual 0 machine # [ 85.057126] systemd[1]: audit.service: Deactivated successfully. machine # [ 85.060105] systemd[1]: Stopped Kernel Auditing. machine # [ 85.067608] systemd[1]: systemd-random-seed.service: Deactivated successfully. machine # [ 85.070467] systemd[1]: Stopped Load/Save OS Random Seed. machine # [ 85.105552] dhcpcd[668]: eth0: deleting address fe80::5054:ff:fe12:3456 machine # [ 85.106934] dhcpcd[668]: eth0: deleting route to 10.0.2.0/24 machine # [ 85.114081] dhcpcd[668]: eth0: deleting default route via 10.0.2.2 machine # [ 85.142863] systemd[1]: systemd-user-sessions.service: Deactivated successfully. machine # [ 85.147663] systemd[1]: Stopped Permit User Sessions. machine # [ 85.148711] systemd[1]: Stopped target Network. machine # [ 85.149766] systemd[1]: Stopped target User and Group Name Lookups. machine # [ 85.151163] systemd[1]: Stopped target Remote File Systems. machine # [ 85.152406] systemd[1]: network-local-commands.service: Deactivated successfully. machine # [ 85.159500] systemd[1]: Stopped Extra networking commands.. machine # [ 85.162863] systemd[1]: network-setup.service: Deactivated successfully. machine # [ 85.165439] make-initrd-ng[2987]: /etc/initrd-release -> /nix/store/yb569afxzi41h46zlippsfc2hwnrqkws-etc-os-release machine # [ 85.168281] make-initrd-ng[2987]: /etc/os-release -> /nix/store/yb569afxzi41h46zlippsfc2hwnrqkws-etc-os-release machine # [ 85.170578] make-initrd-ng[2987]: /shutdown -> /nix/store/9cxd17xnmw0bi8n4nf722ysqj2bjlh8s-systemd-255.4/lib/systemd/systemd-shutdown machine # [ 85.174887] systemd[1]: Stopped Networking Setup. machine # [ 85.199262] systemd[1]: Stopping Address configuration of eth1... machine # [ 85.202762] systemd[1]: Stopping Name Service Cache Daemon (nsncd)... machine # [ 85.208697] systemd[1]: nscd.service: Deactivated successfully. machine # [ 85.214289] systemd[1]: Stopped Name Service Cache Daemon (nsncd). machine # [ 85.247850] make-initrd-ng[2987]: Warning: Couldn't satisfy dependency libc.so.6 for "/nix/store/apab5i73dqa09wx0q27b6fbhd1r18ihl-glibc-2.39-31/lib/libdl.so.2" machine # [ 85.273571] make-initrd-ng[2987]: Warning: Couldn't satisfy dependency ld-linux-x86-64.so.2 for "/nix/store/apab5i73dqa09wx0q27b6fbhd1r18ihl-glibc-2.39-31/lib/libc.so.6" machine # [ 85.334703] network-addresses-eth1-pre-stop[3003]: deleting address 192.168.1.1/24... done machine # [ 85.351939] systemd[1]: save-hwclock.service: Deactivated successfully. machine # [ 85.356534] systemd[1]: Finished Save Hardware Clock. machine # [ 85.361764] systemd[1]: network-addresses-eth1.service: Deactivated successfully. machine # [ 85.366185] systemd[1]: Stopped Address configuration of eth1. machine # [ 85.368381] systemd[1]: Stopped target Preparation for Network. machine # [ 85.374586] systemd[1]: Stopping Firewall... machine # [ 85.377775] systemd[1]: resolvconf.service: Deactivated successfully. machine # [ 85.380153] systemd[1]: Stopped resolvconf update. machine # [ 85.512064] dhcpcd[668]: dhcpcd exited machine # [ 85.514578] systemd[1]: dhcpcd.service: Deactivated successfully. machine # [ 85.518646] systemd[1]: Stopped DHCP Client. machine # [ 85.519684] systemd[1]: dhcpcd.service: Consumed 325ms CPU time, received 96B IP traffic, sent 720B IP traffic. machine # [ 85.524240] systemd[1]: Stopped target Basic System. machine # [ 85.525992] systemd[1]: Stopped target Path Units. machine # [ 85.528647] systemd[1]: Stopped target Slice Units. machine # [ 85.532252] systemd[1]: Removed slice User and Session Slice. machine # [ 85.538664] systemd[1]: Stopped target Socket Units. machine # [ 85.540214] systemd[1]: dbus.socket: Deactivated successfully. machine # [ 85.541625] systemd[1]: Closed D-Bus System Message Bus Socket. machine # [ 85.542650] systemd[1]: nix-daemon.socket: Deactivated successfully. machine # [ 85.543713] systemd[1]: Closed Nix Daemon Socket. machine # [ 85.545606] systemd[1]: Stopped target System Initialization. machine # [ 85.547639] systemd[1]: Stopped target Local Encrypted Volumes. machine # [ 85.550128] systemd[1]: systemd-ask-password-console.path: Deactivated successfully. machine # [ 85.551832] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch. machine # [ 85.553626] systemd[1]: systemd-ask-password-wall.path: Deactivated successfully. machine # [ 85.555901] systemd[1]: Stopped Forward Password Requests to Wall Directory Watch. machine # [ 85.557815] systemd[1]: systemd-oomd.socket: Deactivated successfully. machine # [ 85.559570] systemd[1]: Closed Userspace Out-Of-Memory (OOM) Killer Socket. machine # [ 85.561489] systemd[1]: systemd-sysctl.service: Deactivated successfully. machine # [ 85.563436] systemd[1]: Stopped Apply Kernel Variables. machine # [ 85.567508] systemd[1]: systemd-coredump.socket: Deactivated successfully. machine # [ 85.569696] systemd[1]: Closed Process Core Dump Socket. machine # [ 85.571806] systemd[1]: systemd-update-done.service: Deactivated successfully. machine # [ 85.573553] systemd[1]: Stopped Update is Completed. machine # [ 85.575196] systemd[1]: systemd-journal-catalog-update.service: Deactivated successfully. machine # [ 85.577132] systemd[1]: Stopped Rebuild Journal Catalog. machine # [ 85.578714] systemd[1]: Stopping Record System Boot/Shutdown in UTMP... machine # [ 85.600532] systemd[1]: firewall.service: Deactivated successfully. machine # [ 85.603460] systemd[1]: Stopped Firewall. machine # [ 85.605246] systemd[1]: systemd-modules-load.service: Deactivated successfully. machine # [ 85.606889] systemd[1]: Stopped Load Kernel Modules. machine # [ 85.624960] make-initrd-ng[2987]: Warning: Couldn't satisfy dependency libc.so.6 for "/nix/store/apab5i73dqa09wx0q27b6fbhd1r18ihl-glibc-2.39-31/lib/libm.so.6" machine # [ 85.636749] make-initrd-ng[2987]: Warning: Couldn't satisfy dependency ld-linux-x86-64.so.2 for "/nix/store/apab5i73dqa09wx0q27b6fbhd1r18ihl-glibc-2.39-31/lib/libm.so.6" machine # [ 85.659935] systemd[1]: systemd-update-utmp.service: Deactivated successfully. machine # [ 85.668867] systemd[1]: Stopped Record System Boot/Shutdown in UTMP. machine # [ 85.670311] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully. machine # [ 85.673499] systemd[1]: Stopped Create Volatile Files and Directories. machine # [ 85.674971] systemd[1]: Stopped target Local File Systems. machine # [ 85.680241] systemd[1]: Unmounting /nix/.ro-store... machine # [ 85.687173] systemd[1]: Unmounting /nix/.rw-store... machine # [ 85.690931] systemd[1]: Unmounting /run/keys... machine # [ 85.697166] systemd[1]: Unmounting run-wrappers.mount... machine # [ 85.703215] systemd[1]: Unmounting /tmp/shared... machine # [ 85.720135] systemd[1]: Unmounting /tmp/xchg... machine # [ 85.748875] systemd[1]: nix-.ro\x2dstore.mount: Deactivated successfully. machine # [ 85.762729] systemd[1]: Unmounted /nix/.ro-store. machine # [ 85.769937] systemd[1]: nix-.rw\x2dstore.mount: Deactivated successfully. machine # [ 85.773203] systemd[1]: Unmounted /nix/.rw-store. machine # [ 85.785233] make-initrd-ng[2987]: Warning: Couldn't satisfy dependency libc.so.6 for "/nix/store/apab5i73dqa09wx0q27b6fbhd1r18ihl-glibc-2.39-31/lib/libpthread.so.0" machine # [ 85.791911] systemd[1]: run-wrappers.mount: Deactivated successfully. machine # [ 85.797786] systemd[1]: Unmounted run-wrappers.mount. machine # [ 85.799557] systemd[1]: tmp-shared.mount: Deactivated successfully. machine # [ 85.806518] systemd[1]: Unmounted /tmp/shared. machine # [ 85.812628] systemd[1]: tmp-xchg.mount: Deactivated successfully. machine # [ 85.816829] systemd[1]: Unmounted /tmp/xchg. machine # [ 85.819430] systemd[1]: Stopped target Swaps. machine # [ 85.823955] systemd[1]: run-keys.mount: Deactivated successfully. machine # [ 85.830074] systemd[1]: Unmounted /run/keys. machine # [ 85.835271] systemd[1]: Stopped target Preparation for Local File Systems. machine # [ 85.836700] systemd[1]: Reached target Unmount All Filesystems. machine # [ 85.838808] systemd[1]: systemd-remount-fs.service: Deactivated successfully. machine # [ 85.840390] systemd[1]: Stopped Remount Root and Kernel File Systems. machine # [ 85.842305] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully. machine # [ 85.843827] systemd[1]: Stopped Create Static Device Nodes in /dev. machine # [ 85.845764] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully. machine # [ 85.847517] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully. machine # [ 85.866715] systemd[1]: generate-shutdown-ramfs.service: Deactivated successfully. machine # [ 85.872079] systemd[1]: Finished Generate shutdown ramfs. machine # [ 85.877351] systemd[1]: Reached target System Shutdown. machine # [ 85.879588] systemd[1]: Reached target Late Shutdown Services. machine # [ 85.881401] systemd[1]: systemd-poweroff.service: Deactivated successfully. machine # [ 85.883271] systemd[1]: Finished System Power Off. machine # [ 85.885436] systemd[1]: Reached target System Power Off. machine # [ 85.886562] systemd[1]: Shutting down. machine # [ 85.918784] systemd-udevd[415]: Failed to send readiness notification, ignoring: Connection refused machine # [ 86.113188] systemd-shutdown[1]: Syncing filesystems and block devices. machine # [ 86.122037] systemd-shutdown[1]: Sending SIGTERM to remaining processes... machine # [ 86.126236] systemd-journald[372]: Received SIGTERM from PID 1 (systemd-shutdow). machine # [ 86.146517] systemd-shutdown[1]: Sending SIGKILL to remaining processes... machine # [ 86.150969] systemd-shutdown[1]: Unmounting file systems. machine # [ 86.152380] (sd-remount)[3077]: Remounting '/nix/store' read-only with options 'lowerdir=/mnt-root/nix/.ro-store,upperdir=/mnt-root/nix/.rw-store/store,workdir=/mnt-root/nix/.rw-store/work,uuid=on'. machine # [ 86.169215] (sd-remount)[3078]: Remounting '/nix/store' read-only with options 'lowerdir=/mnt-root/nix/.ro-store,upperdir=/mnt-root/nix/.rw-store/store,workdir=/mnt-root/nix/.rw-store/work,uuid=on'. machine # [ 86.172452] (sd-remount)[3079]: Remounting '/' read-only with options ''. machine # [ 86.181969] EXT4-fs (vda): re-mounted 286efa5a-ee94-441a-af6a-be11226be38d ro. Quota mode: none. machine # [ 86.185105] systemd-shutdown[1]: All filesystems unmounted. machine # [ 86.185814] systemd-shutdown[1]: Deactivating swaps. machine # [ 86.186562] systemd-shutdown[1]: All swaps deactivated. machine # [ 86.187238] systemd-shutdown[1]: Detaching loop devices. machine # [ 86.191164] systemd-shutdown[1]: All loop devices detached. machine # [ 86.192537] systemd-shutdown[1]: Stopping MD devices. machine # [ 86.193724] systemd-shutdown[1]: All MD devices stopped. machine # [ 86.194503] systemd-shutdown[1]: Detaching DM devices. machine # [ 86.195244] systemd-shutdown[1]: All DM devices detached. machine # [ 86.195902] systemd-shutdown[1]: All filesystems, swaps, loop devices, MD devices and DM devices detached. machine # [ 86.205801] systemd-shutdown[1]: Successfully changed into root pivot. machine # [ 86.206601] systemd-shutdown[1]: Returning to initrd... machine # [ 86.223661] shutdown[1]: Syncing filesystems and block devices. machine # [ 86.224827] shutdown[1]: Sending SIGTERM to remaining processes... machine # [ 86.227674] shutdown[1]: Sending SIGKILL to remaining processes... machine # [ 86.230730] shutdown[1]: Unmounting file systems. machine # [ 86.232305] (sd-umoun[3081]: Unmounting '/oldroot/sys/fs/fuse/connections'. machine # [ 86.234048] (sd-umoun[3082]: Unmounting '/oldroot/sys/kernel/config'. machine # [ 86.235706] (sd-umoun[3083]: Unmounting '/oldroot/dev/mqueue'. machine # [ 86.237258] (sd-umoun[3084]: Unmounting '/oldroot/sys/kernel/debug'. machine # [ 86.238890] (sd-umoun[3085]: Unmounting '/oldroot/dev/hugepages'. machine # [ 86.240388] (sd-umoun[3086]: Unmounting '/oldroot/sys/fs/bpf'. machine # [ 86.241979] (sd-umoun[3087]: Unmounting '/oldroot/sys/fs/pstore'. machine # [ 86.243528] (sd-umoun[3088]: Unmounting '/oldroot/sys/fs/cgroup'. machine # [ 86.245309] (sd-umoun[3089]: Unmounting '/oldroot/sys/kernel/security'. machine # [ 86.246927] (sd-umoun[3090]: Unmounting '/oldroot/nix/store'. machine # [ 86.248361] (sd-umoun[3091]: Unmounting '/oldroot/nix/store'. machine # [ 86.554891] (sd-umoun[3092]: Unmounting '/oldroot'. machine # [ 86.555508] (sd-umoun[3092]: Failed to unmount /oldroot: Device or resource busy machine # [ 86.557303] (sd-umoun[3093]: Unmounting '/oldroot/sys'. machine # [ 86.558737] (sd-umoun[3094]: Unmounting '/oldroot/run'. machine # [ 86.560256] (sd-umoun[3095]: Unmounting '/oldroot/proc'. machine # [ 86.561716] (sd-umoun[3096]: Unmounting '/oldroot/dev/shm'. machine # [ 86.563283] (sd-umoun[3097]: Unmounting '/oldroot/dev/pts'. machine # [ 86.564770] (sd-umoun[3098]: Unmounting '/oldroot/dev'. machine # [ 86.566485] (sd-umoun[3099]: Unmounting '/oldroot'. machine # [ 86.671574] EXT4-fs (vda): unmounting filesystem 286efa5a-ee94-441a-af6a-be11226be38d. machine # [ 86.674000] shutdown[1]: All filesystems unmounted. machine # [ 86.674582] shutdown[1]: Deactivating swaps. machine # [ 86.675216] shutdown[1]: All swaps deactivated. machine # [ 86.675756] shutdown[1]: Detaching loop devices. machine # [ 86.677168] shutdown[1]: All loop devices detached. machine # [ 86.677750] shutdown[1]: Stopping MD devices. machine # [ 86.678404] shutdown[1]: All MD devices stopped. machine # [ 86.679023] shutdown[1]: Detaching DM devices. machine # [ 86.679672] shutdown[1]: All DM devices detached. machine # [ 86.680269] shutdown[1]: All filesystems, swaps, loop devices, MD devices and DM devices detached. machine # [ 86.681780] shutdown[1]: Syncing filesystems and block devices. machine # [ 86.682955] shutdown[1]: Powering off. machine # [ 86.684064] ACPI: PM: Preparing to enter system sleep state S5 machine # [ 86.684787] kvm: exiting hardware virtualization machine # [ 86.685366] reboot: Power down (finished: waiting for the VM to power off, in 2.06 seconds) (finished: run the VM test script, in 87.44 seconds) test script finished in 87.44s cleanup (finished: cleanup, in 0.00 seconds) kill vlan (pid 5)