Sep 12 22:55:44.271181 kernel: Linux version 6.12.47-flatcar (build@pony-truck.infra.kinvolk.io) (x86_64-cros-linux-gnu-gcc (Gentoo Hardened 14.3.0 p8) 14.3.0, GNU ld (Gentoo 2.44 p4) 2.44.0) #1 SMP PREEMPT_DYNAMIC Fri Sep 12 20:38:35 -00 2025 Sep 12 22:55:44.271211 kernel: Command line: BOOT_IMAGE=/flatcar/vmlinuz-a mount.usr=/dev/mapper/usr verity.usr=PARTUUID=7130c94a-213a-4e5a-8e26-6cce9662f132 rootflags=rw mount.usrflags=ro consoleblank=0 root=LABEL=ROOT console=ttyS0,115200 flatcar.first_boot=detected verity.usrhash=8e60d6befc710e967d67e9a1d87ced7416895090c99a765b3a00e66a62f49e40 Sep 12 22:55:44.271222 kernel: BIOS-provided physical RAM map: Sep 12 22:55:44.271230 kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable Sep 12 22:55:44.271238 kernel: BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved Sep 12 22:55:44.271246 kernel: BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved Sep 12 22:55:44.271255 kernel: BIOS-e820: [mem 0x0000000000100000-0x000000009cfdbfff] usable Sep 12 22:55:44.271263 kernel: BIOS-e820: [mem 0x000000009cfdc000-0x000000009cffffff] reserved Sep 12 22:55:44.271288 kernel: BIOS-e820: [mem 0x00000000b0000000-0x00000000bfffffff] reserved Sep 12 22:55:44.271302 kernel: BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved Sep 12 22:55:44.271311 kernel: BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved Sep 12 22:55:44.271320 kernel: BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved Sep 12 22:55:44.277422 kernel: BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved Sep 12 22:55:44.277434 kernel: NX (Execute Disable) protection: active Sep 12 22:55:44.277453 kernel: APIC: Static calls initialized Sep 12 22:55:44.277462 kernel: SMBIOS 2.8 present. Sep 12 22:55:44.277471 kernel: DMI: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014 Sep 12 22:55:44.277480 kernel: DMI: Memory slots populated: 1/1 Sep 12 22:55:44.277488 kernel: Hypervisor detected: KVM Sep 12 22:55:44.277497 kernel: kvm-clock: Using msrs 4b564d01 and 4b564d00 Sep 12 22:55:44.277505 kernel: kvm-clock: using sched offset of 8213094378 cycles Sep 12 22:55:44.277516 kernel: clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns Sep 12 22:55:44.277525 kernel: tsc: Detected 2794.748 MHz processor Sep 12 22:55:44.277537 kernel: e820: update [mem 0x00000000-0x00000fff] usable ==> reserved Sep 12 22:55:44.277546 kernel: e820: remove [mem 0x000a0000-0x000fffff] usable Sep 12 22:55:44.277555 kernel: last_pfn = 0x9cfdc max_arch_pfn = 0x400000000 Sep 12 22:55:44.277564 kernel: MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs Sep 12 22:55:44.277573 kernel: x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT Sep 12 22:55:44.277582 kernel: Using GB pages for direct mapping Sep 12 22:55:44.277591 kernel: ACPI: Early table checksum verification disabled Sep 12 22:55:44.277600 kernel: ACPI: RSDP 0x00000000000F59D0 000014 (v00 BOCHS ) Sep 12 22:55:44.277609 kernel: ACPI: RSDT 0x000000009CFE241A 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) Sep 12 22:55:44.277621 kernel: ACPI: FACP 0x000000009CFE21FA 0000F4 (v03 BOCHS BXPC 00000001 BXPC 00000001) Sep 12 22:55:44.277630 kernel: ACPI: DSDT 0x000000009CFE0040 0021BA (v01 BOCHS BXPC 00000001 BXPC 00000001) Sep 12 22:55:44.277639 kernel: ACPI: FACS 0x000000009CFE0000 000040 Sep 12 22:55:44.277647 kernel: ACPI: APIC 0x000000009CFE22EE 000090 (v01 BOCHS BXPC 00000001 BXPC 00000001) Sep 12 22:55:44.277656 kernel: ACPI: HPET 0x000000009CFE237E 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) Sep 12 22:55:44.277666 kernel: ACPI: MCFG 0x000000009CFE23B6 00003C (v01 BOCHS BXPC 00000001 BXPC 00000001) Sep 12 22:55:44.277674 kernel: ACPI: WAET 0x000000009CFE23F2 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) Sep 12 22:55:44.277683 kernel: ACPI: Reserving FACP table memory at [mem 0x9cfe21fa-0x9cfe22ed] Sep 12 22:55:44.277698 kernel: ACPI: Reserving DSDT table memory at [mem 0x9cfe0040-0x9cfe21f9] Sep 12 22:55:44.277707 kernel: ACPI: Reserving FACS table memory at [mem 0x9cfe0000-0x9cfe003f] Sep 12 22:55:44.277717 kernel: ACPI: Reserving APIC table memory at [mem 0x9cfe22ee-0x9cfe237d] Sep 12 22:55:44.277726 kernel: ACPI: Reserving HPET table memory at [mem 0x9cfe237e-0x9cfe23b5] Sep 12 22:55:44.277735 kernel: ACPI: Reserving MCFG table memory at [mem 0x9cfe23b6-0x9cfe23f1] Sep 12 22:55:44.277744 kernel: ACPI: Reserving WAET table memory at [mem 0x9cfe23f2-0x9cfe2419] Sep 12 22:55:44.277756 kernel: No NUMA configuration found Sep 12 22:55:44.277765 kernel: Faking a node at [mem 0x0000000000000000-0x000000009cfdbfff] Sep 12 22:55:44.277775 kernel: NODE_DATA(0) allocated [mem 0x9cfd4dc0-0x9cfdbfff] Sep 12 22:55:44.277785 kernel: Zone ranges: Sep 12 22:55:44.277794 kernel: DMA [mem 0x0000000000001000-0x0000000000ffffff] Sep 12 22:55:44.277803 kernel: DMA32 [mem 0x0000000001000000-0x000000009cfdbfff] Sep 12 22:55:44.277813 kernel: Normal empty Sep 12 22:55:44.277822 kernel: Device empty Sep 12 22:55:44.277831 kernel: Movable zone start for each node Sep 12 22:55:44.277841 kernel: Early memory node ranges Sep 12 22:55:44.277852 kernel: node 0: [mem 0x0000000000001000-0x000000000009efff] Sep 12 22:55:44.277862 kernel: node 0: [mem 0x0000000000100000-0x000000009cfdbfff] Sep 12 22:55:44.277871 kernel: Initmem setup node 0 [mem 0x0000000000001000-0x000000009cfdbfff] Sep 12 22:55:44.277880 kernel: On node 0, zone DMA: 1 pages in unavailable ranges Sep 12 22:55:44.277890 kernel: On node 0, zone DMA: 97 pages in unavailable ranges Sep 12 22:55:44.277899 kernel: On node 0, zone DMA32: 12324 pages in unavailable ranges Sep 12 22:55:44.277909 kernel: ACPI: PM-Timer IO Port: 0x608 Sep 12 22:55:44.277918 kernel: ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) Sep 12 22:55:44.277928 kernel: IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 Sep 12 22:55:44.277940 kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) Sep 12 22:55:44.277950 kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) Sep 12 22:55:44.277959 kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) Sep 12 22:55:44.277969 kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) Sep 12 22:55:44.277978 kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) Sep 12 22:55:44.277988 kernel: ACPI: Using ACPI (MADT) for SMP configuration information Sep 12 22:55:44.277997 kernel: ACPI: HPET id: 0x8086a201 base: 0xfed00000 Sep 12 22:55:44.278006 kernel: TSC deadline timer available Sep 12 22:55:44.278016 kernel: CPU topo: Max. logical packages: 1 Sep 12 22:55:44.278027 kernel: CPU topo: Max. logical dies: 1 Sep 12 22:55:44.278037 kernel: CPU topo: Max. dies per package: 1 Sep 12 22:55:44.278046 kernel: CPU topo: Max. threads per core: 1 Sep 12 22:55:44.278055 kernel: CPU topo: Num. cores per package: 4 Sep 12 22:55:44.278065 kernel: CPU topo: Num. threads per package: 4 Sep 12 22:55:44.278074 kernel: CPU topo: Allowing 4 present CPUs plus 0 hotplug CPUs Sep 12 22:55:44.278083 kernel: kvm-guest: APIC: eoi() replaced with kvm_guest_apic_eoi_write() Sep 12 22:55:44.278093 kernel: kvm-guest: KVM setup pv remote TLB flush Sep 12 22:55:44.278102 kernel: kvm-guest: setup PV sched yield Sep 12 22:55:44.278114 kernel: [mem 0xc0000000-0xfed1bfff] available for PCI devices Sep 12 22:55:44.278124 kernel: Booting paravirtualized kernel on KVM Sep 12 22:55:44.278133 kernel: clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns Sep 12 22:55:44.278143 kernel: setup_percpu: NR_CPUS:512 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 Sep 12 22:55:44.278152 kernel: percpu: Embedded 60 pages/cpu s207832 r8192 d29736 u524288 Sep 12 22:55:44.278162 kernel: pcpu-alloc: s207832 r8192 d29736 u524288 alloc=1*2097152 Sep 12 22:55:44.278171 kernel: pcpu-alloc: [0] 0 1 2 3 Sep 12 22:55:44.278180 kernel: kvm-guest: PV spinlocks enabled Sep 12 22:55:44.278190 kernel: PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) Sep 12 22:55:44.278203 kernel: Kernel command line: rootflags=rw mount.usrflags=ro BOOT_IMAGE=/flatcar/vmlinuz-a mount.usr=/dev/mapper/usr verity.usr=PARTUUID=7130c94a-213a-4e5a-8e26-6cce9662f132 rootflags=rw mount.usrflags=ro consoleblank=0 root=LABEL=ROOT console=ttyS0,115200 flatcar.first_boot=detected verity.usrhash=8e60d6befc710e967d67e9a1d87ced7416895090c99a765b3a00e66a62f49e40 Sep 12 22:55:44.278213 kernel: Unknown kernel command line parameters "BOOT_IMAGE=/flatcar/vmlinuz-a", will be passed to user space. Sep 12 22:55:44.278222 kernel: random: crng init done Sep 12 22:55:44.278232 kernel: Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear) Sep 12 22:55:44.278241 kernel: Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear) Sep 12 22:55:44.278251 kernel: Fallback order for Node 0: 0 Sep 12 22:55:44.278260 kernel: Built 1 zonelists, mobility grouping on. Total pages: 642938 Sep 12 22:55:44.278270 kernel: Policy zone: DMA32 Sep 12 22:55:44.279342 kernel: mem auto-init: stack:off, heap alloc:off, heap free:off Sep 12 22:55:44.279354 kernel: SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 Sep 12 22:55:44.279364 kernel: ftrace: allocating 40125 entries in 157 pages Sep 12 22:55:44.279373 kernel: ftrace: allocated 157 pages with 5 groups Sep 12 22:55:44.279382 kernel: Dynamic Preempt: voluntary Sep 12 22:55:44.279392 kernel: rcu: Preemptible hierarchical RCU implementation. Sep 12 22:55:44.279403 kernel: rcu: RCU event tracing is enabled. Sep 12 22:55:44.279412 kernel: rcu: RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=4. Sep 12 22:55:44.279422 kernel: Trampoline variant of Tasks RCU enabled. Sep 12 22:55:44.279435 kernel: Rude variant of Tasks RCU enabled. Sep 12 22:55:44.279444 kernel: Tracing variant of Tasks RCU enabled. Sep 12 22:55:44.279453 kernel: rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. Sep 12 22:55:44.279463 kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 Sep 12 22:55:44.279472 kernel: RCU Tasks: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=4. Sep 12 22:55:44.279482 kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=4. Sep 12 22:55:44.279491 kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=4. Sep 12 22:55:44.279501 kernel: NR_IRQS: 33024, nr_irqs: 456, preallocated irqs: 16 Sep 12 22:55:44.279510 kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. Sep 12 22:55:44.279529 kernel: Console: colour VGA+ 80x25 Sep 12 22:55:44.279539 kernel: printk: legacy console [ttyS0] enabled Sep 12 22:55:44.279549 kernel: ACPI: Core revision 20240827 Sep 12 22:55:44.279561 kernel: clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns Sep 12 22:55:44.279570 kernel: APIC: Switch to symmetric I/O mode setup Sep 12 22:55:44.279580 kernel: x2apic enabled Sep 12 22:55:44.279590 kernel: APIC: Switched APIC routing to: physical x2apic Sep 12 22:55:44.279600 kernel: kvm-guest: APIC: send_IPI_mask() replaced with kvm_send_ipi_mask() Sep 12 22:55:44.279610 kernel: kvm-guest: APIC: send_IPI_mask_allbutself() replaced with kvm_send_ipi_mask_allbutself() Sep 12 22:55:44.279622 kernel: kvm-guest: setup PV IPIs Sep 12 22:55:44.279632 kernel: ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 Sep 12 22:55:44.279642 kernel: clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x2848df6a9de, max_idle_ns: 440795280912 ns Sep 12 22:55:44.279652 kernel: Calibrating delay loop (skipped) preset value.. 5589.49 BogoMIPS (lpj=2794748) Sep 12 22:55:44.279662 kernel: x86/cpu: User Mode Instruction Prevention (UMIP) activated Sep 12 22:55:44.279672 kernel: Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127 Sep 12 22:55:44.279681 kernel: Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0 Sep 12 22:55:44.279691 kernel: Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization Sep 12 22:55:44.279703 kernel: Spectre V2 : Mitigation: Retpolines Sep 12 22:55:44.279713 kernel: Spectre V2 : Spectre v2 / SpectreRSB: Filling RSB on context switch and VMEXIT Sep 12 22:55:44.279723 kernel: Spectre V2 : Enabling Speculation Barrier for firmware calls Sep 12 22:55:44.279732 kernel: active return thunk: retbleed_return_thunk Sep 12 22:55:44.279742 kernel: RETBleed: Mitigation: untrained return thunk Sep 12 22:55:44.279752 kernel: Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier Sep 12 22:55:44.279761 kernel: Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl Sep 12 22:55:44.279771 kernel: Speculative Return Stack Overflow: IBPB-extending microcode not applied! Sep 12 22:55:44.279785 kernel: Speculative Return Stack Overflow: WARNING: See https://kernel.org/doc/html/latest/admin-guide/hw-vuln/srso.html for mitigation options. Sep 12 22:55:44.279795 kernel: active return thunk: srso_return_thunk Sep 12 22:55:44.279804 kernel: Speculative Return Stack Overflow: Vulnerable: Safe RET, no microcode Sep 12 22:55:44.279814 kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' Sep 12 22:55:44.279824 kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' Sep 12 22:55:44.279834 kernel: x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' Sep 12 22:55:44.279843 kernel: x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 Sep 12 22:55:44.279853 kernel: x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'compacted' format. Sep 12 22:55:44.279863 kernel: Freeing SMP alternatives memory: 32K Sep 12 22:55:44.279875 kernel: pid_max: default: 32768 minimum: 301 Sep 12 22:55:44.279885 kernel: LSM: initializing lsm=lockdown,capability,landlock,selinux,ima Sep 12 22:55:44.279894 kernel: landlock: Up and running. Sep 12 22:55:44.279904 kernel: SELinux: Initializing. Sep 12 22:55:44.279914 kernel: Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear) Sep 12 22:55:44.279924 kernel: Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear) Sep 12 22:55:44.279933 kernel: smpboot: CPU0: AMD EPYC 7402P 24-Core Processor (family: 0x17, model: 0x31, stepping: 0x0) Sep 12 22:55:44.279943 kernel: Performance Events: Fam17h+ core perfctr, AMD PMU driver. Sep 12 22:55:44.279953 kernel: ... version: 0 Sep 12 22:55:44.279965 kernel: ... bit width: 48 Sep 12 22:55:44.279974 kernel: ... generic registers: 6 Sep 12 22:55:44.279984 kernel: ... value mask: 0000ffffffffffff Sep 12 22:55:44.279994 kernel: ... max period: 00007fffffffffff Sep 12 22:55:44.280003 kernel: ... fixed-purpose events: 0 Sep 12 22:55:44.280013 kernel: ... event mask: 000000000000003f Sep 12 22:55:44.280023 kernel: signal: max sigframe size: 1776 Sep 12 22:55:44.280032 kernel: rcu: Hierarchical SRCU implementation. Sep 12 22:55:44.280042 kernel: rcu: Max phase no-delay instances is 400. Sep 12 22:55:44.280057 kernel: Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level Sep 12 22:55:44.280069 kernel: smp: Bringing up secondary CPUs ... Sep 12 22:55:44.280081 kernel: smpboot: x86: Booting SMP configuration: Sep 12 22:55:44.280093 kernel: .... node #0, CPUs: #1 #2 #3 Sep 12 22:55:44.280105 kernel: smp: Brought up 1 node, 4 CPUs Sep 12 22:55:44.280117 kernel: smpboot: Total of 4 processors activated (22357.98 BogoMIPS) Sep 12 22:55:44.280129 kernel: Memory: 2428920K/2571752K available (14336K kernel code, 2432K rwdata, 9992K rodata, 54084K init, 2880K bss, 136904K reserved, 0K cma-reserved) Sep 12 22:55:44.280141 kernel: devtmpfs: initialized Sep 12 22:55:44.280153 kernel: x86/mm: Memory block size: 128MB Sep 12 22:55:44.280169 kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns Sep 12 22:55:44.280181 kernel: futex hash table entries: 1024 (order: 4, 65536 bytes, linear) Sep 12 22:55:44.280193 kernel: pinctrl core: initialized pinctrl subsystem Sep 12 22:55:44.280203 kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family Sep 12 22:55:44.280212 kernel: audit: initializing netlink subsys (disabled) Sep 12 22:55:44.280222 kernel: audit: type=2000 audit(1757717739.395:1): state=initialized audit_enabled=0 res=1 Sep 12 22:55:44.280232 kernel: thermal_sys: Registered thermal governor 'step_wise' Sep 12 22:55:44.280241 kernel: thermal_sys: Registered thermal governor 'user_space' Sep 12 22:55:44.280251 kernel: cpuidle: using governor menu Sep 12 22:55:44.280263 kernel: acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 Sep 12 22:55:44.280281 kernel: dca service started, version 1.12.1 Sep 12 22:55:44.280299 kernel: PCI: ECAM [mem 0xb0000000-0xbfffffff] (base 0xb0000000) for domain 0000 [bus 00-ff] Sep 12 22:55:44.280310 kernel: PCI: ECAM [mem 0xb0000000-0xbfffffff] reserved as E820 entry Sep 12 22:55:44.280320 kernel: PCI: Using configuration type 1 for base access Sep 12 22:55:44.280329 kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. Sep 12 22:55:44.280355 kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages Sep 12 22:55:44.280365 kernel: HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page Sep 12 22:55:44.280375 kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages Sep 12 22:55:44.280389 kernel: HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page Sep 12 22:55:44.280399 kernel: ACPI: Added _OSI(Module Device) Sep 12 22:55:44.280408 kernel: ACPI: Added _OSI(Processor Device) Sep 12 22:55:44.280418 kernel: ACPI: Added _OSI(Processor Aggregator Device) Sep 12 22:55:44.280428 kernel: ACPI: 1 ACPI AML tables successfully acquired and loaded Sep 12 22:55:44.280438 kernel: ACPI: Interpreter enabled Sep 12 22:55:44.280447 kernel: ACPI: PM: (supports S0 S3 S5) Sep 12 22:55:44.280457 kernel: ACPI: Using IOAPIC for interrupt routing Sep 12 22:55:44.280467 kernel: PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug Sep 12 22:55:44.280479 kernel: PCI: Using E820 reservations for host bridge windows Sep 12 22:55:44.280489 kernel: ACPI: Enabled 2 GPEs in block 00 to 3F Sep 12 22:55:44.280499 kernel: ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) Sep 12 22:55:44.282473 kernel: acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3] Sep 12 22:55:44.282624 kernel: acpi PNP0A08:00: _OSC: platform does not support [PCIeHotplug LTR] Sep 12 22:55:44.282758 kernel: acpi PNP0A08:00: _OSC: OS now controls [PME AER PCIeCapability] Sep 12 22:55:44.282771 kernel: PCI host bridge to bus 0000:00 Sep 12 22:55:44.282926 kernel: pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] Sep 12 22:55:44.283052 kernel: pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] Sep 12 22:55:44.283186 kernel: pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] Sep 12 22:55:44.283395 kernel: pci_bus 0000:00: root bus resource [mem 0x9d000000-0xafffffff window] Sep 12 22:55:44.283549 kernel: pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] Sep 12 22:55:44.283698 kernel: pci_bus 0000:00: root bus resource [mem 0x100000000-0x8ffffffff window] Sep 12 22:55:44.283847 kernel: pci_bus 0000:00: root bus resource [bus 00-ff] Sep 12 22:55:44.284069 kernel: pci 0000:00:00.0: [8086:29c0] type 00 class 0x060000 conventional PCI endpoint Sep 12 22:55:44.286354 kernel: pci 0000:00:01.0: [1234:1111] type 00 class 0x030000 conventional PCI endpoint Sep 12 22:55:44.286524 kernel: pci 0000:00:01.0: BAR 0 [mem 0xfd000000-0xfdffffff pref] Sep 12 22:55:44.286660 kernel: pci 0000:00:01.0: BAR 2 [mem 0xfebd0000-0xfebd0fff] Sep 12 22:55:44.286796 kernel: pci 0000:00:01.0: ROM [mem 0xfebc0000-0xfebcffff pref] Sep 12 22:55:44.286931 kernel: pci 0000:00:01.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff] Sep 12 22:55:44.287088 kernel: pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint Sep 12 22:55:44.287232 kernel: pci 0000:00:02.0: BAR 0 [io 0xc0c0-0xc0df] Sep 12 22:55:44.287424 kernel: pci 0000:00:02.0: BAR 1 [mem 0xfebd1000-0xfebd1fff] Sep 12 22:55:44.287585 kernel: pci 0000:00:02.0: BAR 4 [mem 0xfe000000-0xfe003fff 64bit pref] Sep 12 22:55:44.287761 kernel: pci 0000:00:03.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint Sep 12 22:55:44.287915 kernel: pci 0000:00:03.0: BAR 0 [io 0xc000-0xc07f] Sep 12 22:55:44.288068 kernel: pci 0000:00:03.0: BAR 1 [mem 0xfebd2000-0xfebd2fff] Sep 12 22:55:44.288227 kernel: pci 0000:00:03.0: BAR 4 [mem 0xfe004000-0xfe007fff 64bit pref] Sep 12 22:55:44.288485 kernel: pci 0000:00:04.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint Sep 12 22:55:44.288633 kernel: pci 0000:00:04.0: BAR 0 [io 0xc0e0-0xc0ff] Sep 12 22:55:44.288767 kernel: pci 0000:00:04.0: BAR 1 [mem 0xfebd3000-0xfebd3fff] Sep 12 22:55:44.288900 kernel: pci 0000:00:04.0: BAR 4 [mem 0xfe008000-0xfe00bfff 64bit pref] Sep 12 22:55:44.289033 kernel: pci 0000:00:04.0: ROM [mem 0xfeb80000-0xfebbffff pref] Sep 12 22:55:44.289198 kernel: pci 0000:00:1f.0: [8086:2918] type 00 class 0x060100 conventional PCI endpoint Sep 12 22:55:44.291879 kernel: pci 0000:00:1f.0: quirk: [io 0x0600-0x067f] claimed by ICH6 ACPI/GPIO/TCO Sep 12 22:55:44.292049 kernel: pci 0000:00:1f.2: [8086:2922] type 00 class 0x010601 conventional PCI endpoint Sep 12 22:55:44.292188 kernel: pci 0000:00:1f.2: BAR 4 [io 0xc100-0xc11f] Sep 12 22:55:44.292366 kernel: pci 0000:00:1f.2: BAR 5 [mem 0xfebd4000-0xfebd4fff] Sep 12 22:55:44.292528 kernel: pci 0000:00:1f.3: [8086:2930] type 00 class 0x0c0500 conventional PCI endpoint Sep 12 22:55:44.292671 kernel: pci 0000:00:1f.3: BAR 4 [io 0x0700-0x073f] Sep 12 22:55:44.292693 kernel: ACPI: PCI: Interrupt link LNKA configured for IRQ 10 Sep 12 22:55:44.294869 kernel: ACPI: PCI: Interrupt link LNKB configured for IRQ 10 Sep 12 22:55:44.294883 kernel: ACPI: PCI: Interrupt link LNKC configured for IRQ 11 Sep 12 22:55:44.294893 kernel: ACPI: PCI: Interrupt link LNKD configured for IRQ 11 Sep 12 22:55:44.294902 kernel: ACPI: PCI: Interrupt link LNKE configured for IRQ 10 Sep 12 22:55:44.294912 kernel: ACPI: PCI: Interrupt link LNKF configured for IRQ 10 Sep 12 22:55:44.294922 kernel: ACPI: PCI: Interrupt link LNKG configured for IRQ 11 Sep 12 22:55:44.294931 kernel: ACPI: PCI: Interrupt link LNKH configured for IRQ 11 Sep 12 22:55:44.294941 kernel: ACPI: PCI: Interrupt link GSIA configured for IRQ 16 Sep 12 22:55:44.294951 kernel: ACPI: PCI: Interrupt link GSIB configured for IRQ 17 Sep 12 22:55:44.294967 kernel: ACPI: PCI: Interrupt link GSIC configured for IRQ 18 Sep 12 22:55:44.294977 kernel: ACPI: PCI: Interrupt link GSID configured for IRQ 19 Sep 12 22:55:44.294987 kernel: ACPI: PCI: Interrupt link GSIE configured for IRQ 20 Sep 12 22:55:44.294997 kernel: ACPI: PCI: Interrupt link GSIF configured for IRQ 21 Sep 12 22:55:44.295007 kernel: ACPI: PCI: Interrupt link GSIG configured for IRQ 22 Sep 12 22:55:44.295017 kernel: ACPI: PCI: Interrupt link GSIH configured for IRQ 23 Sep 12 22:55:44.295027 kernel: iommu: Default domain type: Translated Sep 12 22:55:44.295037 kernel: iommu: DMA domain TLB invalidation policy: lazy mode Sep 12 22:55:44.295047 kernel: PCI: Using ACPI for IRQ routing Sep 12 22:55:44.295059 kernel: PCI: pci_cache_line_size set to 64 bytes Sep 12 22:55:44.295069 kernel: e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff] Sep 12 22:55:44.295079 kernel: e820: reserve RAM buffer [mem 0x9cfdc000-0x9fffffff] Sep 12 22:55:44.295240 kernel: pci 0000:00:01.0: vgaarb: setting as boot VGA device Sep 12 22:55:44.295440 kernel: pci 0000:00:01.0: vgaarb: bridge control possible Sep 12 22:55:44.295609 kernel: pci 0000:00:01.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none Sep 12 22:55:44.295625 kernel: vgaarb: loaded Sep 12 22:55:44.295637 kernel: hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 Sep 12 22:55:44.295654 kernel: hpet0: 3 comparators, 64-bit 100.000000 MHz counter Sep 12 22:55:44.295666 kernel: clocksource: Switched to clocksource kvm-clock Sep 12 22:55:44.295676 kernel: VFS: Disk quotas dquot_6.6.0 Sep 12 22:55:44.295687 kernel: VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) Sep 12 22:55:44.295698 kernel: pnp: PnP ACPI init Sep 12 22:55:44.295886 kernel: system 00:05: [mem 0xb0000000-0xbfffffff window] has been reserved Sep 12 22:55:44.295904 kernel: pnp: PnP ACPI: found 6 devices Sep 12 22:55:44.295915 kernel: clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns Sep 12 22:55:44.295931 kernel: NET: Registered PF_INET protocol family Sep 12 22:55:44.295942 kernel: IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear) Sep 12 22:55:44.295953 kernel: tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear) Sep 12 22:55:44.295964 kernel: Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear) Sep 12 22:55:44.295975 kernel: TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear) Sep 12 22:55:44.295986 kernel: TCP bind hash table entries: 32768 (order: 8, 1048576 bytes, linear) Sep 12 22:55:44.295997 kernel: TCP: Hash tables configured (established 32768 bind 32768) Sep 12 22:55:44.296008 kernel: UDP hash table entries: 2048 (order: 4, 65536 bytes, linear) Sep 12 22:55:44.296019 kernel: UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear) Sep 12 22:55:44.296032 kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family Sep 12 22:55:44.296043 kernel: NET: Registered PF_XDP protocol family Sep 12 22:55:44.296189 kernel: pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] Sep 12 22:55:44.296367 kernel: pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] Sep 12 22:55:44.296868 kernel: pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] Sep 12 22:55:44.297007 kernel: pci_bus 0000:00: resource 7 [mem 0x9d000000-0xafffffff window] Sep 12 22:55:44.297141 kernel: pci_bus 0000:00: resource 8 [mem 0xc0000000-0xfebfffff window] Sep 12 22:55:44.297766 kernel: pci_bus 0000:00: resource 9 [mem 0x100000000-0x8ffffffff window] Sep 12 22:55:44.297789 kernel: PCI: CLS 0 bytes, default 64 Sep 12 22:55:44.297800 kernel: clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2848df6a9de, max_idle_ns: 440795280912 ns Sep 12 22:55:44.297811 kernel: Initialise system trusted keyrings Sep 12 22:55:44.297821 kernel: workingset: timestamp_bits=39 max_order=20 bucket_order=0 Sep 12 22:55:44.297831 kernel: Key type asymmetric registered Sep 12 22:55:44.297841 kernel: Asymmetric key parser 'x509' registered Sep 12 22:55:44.297851 kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) Sep 12 22:55:44.297861 kernel: io scheduler mq-deadline registered Sep 12 22:55:44.297871 kernel: io scheduler kyber registered Sep 12 22:55:44.297884 kernel: io scheduler bfq registered Sep 12 22:55:44.297893 kernel: ioatdma: Intel(R) QuickData Technology Driver 5.00 Sep 12 22:55:44.297904 kernel: ACPI: \_SB_.GSIG: Enabled at IRQ 22 Sep 12 22:55:44.297914 kernel: ACPI: \_SB_.GSIH: Enabled at IRQ 23 Sep 12 22:55:44.297924 kernel: ACPI: \_SB_.GSIE: Enabled at IRQ 20 Sep 12 22:55:44.297934 kernel: Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled Sep 12 22:55:44.297944 kernel: 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A Sep 12 22:55:44.297954 kernel: i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 Sep 12 22:55:44.297964 kernel: serio: i8042 KBD port at 0x60,0x64 irq 1 Sep 12 22:55:44.297976 kernel: serio: i8042 AUX port at 0x60,0x64 irq 12 Sep 12 22:55:44.298144 kernel: rtc_cmos 00:04: RTC can wake from S4 Sep 12 22:55:44.298162 kernel: input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0 Sep 12 22:55:44.298328 kernel: rtc_cmos 00:04: registered as rtc0 Sep 12 22:55:44.298489 kernel: rtc_cmos 00:04: setting system clock to 2025-09-12T22:55:43 UTC (1757717743) Sep 12 22:55:44.298618 kernel: rtc_cmos 00:04: alarms up to one day, y3k, 242 bytes nvram, hpet irqs Sep 12 22:55:44.298631 kernel: amd_pstate: the _CPC object is not present in SBIOS or ACPI disabled Sep 12 22:55:44.298641 kernel: NET: Registered PF_INET6 protocol family Sep 12 22:55:44.298656 kernel: Segment Routing with IPv6 Sep 12 22:55:44.298666 kernel: In-situ OAM (IOAM) with IPv6 Sep 12 22:55:44.298676 kernel: NET: Registered PF_PACKET protocol family Sep 12 22:55:44.298686 kernel: Key type dns_resolver registered Sep 12 22:55:44.298696 kernel: IPI shorthand broadcast: enabled Sep 12 22:55:44.298706 kernel: sched_clock: Marking stable (4899003642, 156987333)->(5203718829, -147727854) Sep 12 22:55:44.298715 kernel: registered taskstats version 1 Sep 12 22:55:44.298725 kernel: Loading compiled-in X.509 certificates Sep 12 22:55:44.298735 kernel: Loaded X.509 cert 'Kinvolk GmbH: Module signing key for 6.12.47-flatcar: c3297a5801573420030c321362a802da1fd49c4e' Sep 12 22:55:44.298748 kernel: Demotion targets for Node 0: null Sep 12 22:55:44.298758 kernel: Key type .fscrypt registered Sep 12 22:55:44.298767 kernel: Key type fscrypt-provisioning registered Sep 12 22:55:44.298778 kernel: ima: No TPM chip found, activating TPM-bypass! Sep 12 22:55:44.298787 kernel: ima: Allocated hash algorithm: sha1 Sep 12 22:55:44.298797 kernel: ima: No architecture policies found Sep 12 22:55:44.298807 kernel: clk: Disabling unused clocks Sep 12 22:55:44.298817 kernel: Warning: unable to open an initial console. Sep 12 22:55:44.298827 kernel: Freeing unused kernel image (initmem) memory: 54084K Sep 12 22:55:44.298839 kernel: Write protecting the kernel read-only data: 24576k Sep 12 22:55:44.298850 kernel: Freeing unused kernel image (rodata/data gap) memory: 248K Sep 12 22:55:44.298859 kernel: Run /init as init process Sep 12 22:55:44.298869 kernel: with arguments: Sep 12 22:55:44.298879 kernel: /init Sep 12 22:55:44.298889 kernel: with environment: Sep 12 22:55:44.298898 kernel: HOME=/ Sep 12 22:55:44.298908 kernel: TERM=linux Sep 12 22:55:44.298917 kernel: BOOT_IMAGE=/flatcar/vmlinuz-a Sep 12 22:55:44.298931 systemd[1]: Successfully made /usr/ read-only. Sep 12 22:55:44.298957 systemd[1]: systemd 256.8 running in system mode (+PAM +AUDIT +SELINUX -APPARMOR +IMA +SMACK +SECCOMP -GCRYPT -GNUTLS +OPENSSL -ACL +BLKID +CURL +ELFUTILS -FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK -XKBCOMMON +UTMP -SYSVINIT +LIBARCHIVE) Sep 12 22:55:44.298971 systemd[1]: Detected virtualization kvm. Sep 12 22:55:44.298982 systemd[1]: Detected architecture x86-64. Sep 12 22:55:44.298992 systemd[1]: Running in initrd. Sep 12 22:55:44.299005 systemd[1]: No hostname configured, using default hostname. Sep 12 22:55:44.299016 systemd[1]: Hostname set to . Sep 12 22:55:44.299030 systemd[1]: Initializing machine ID from VM UUID. Sep 12 22:55:44.299040 systemd[1]: Queued start job for default target initrd.target. Sep 12 22:55:44.299052 systemd[1]: Started clevis-luks-askpass.path - Forward Password Requests to Clevis Directory Watch. Sep 12 22:55:44.299063 systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. Sep 12 22:55:44.299074 systemd[1]: Expecting device dev-disk-by\x2dlabel-EFI\x2dSYSTEM.device - /dev/disk/by-label/EFI-SYSTEM... Sep 12 22:55:44.299085 systemd[1]: Expecting device dev-disk-by\x2dlabel-OEM.device - /dev/disk/by-label/OEM... Sep 12 22:55:44.299099 systemd[1]: Expecting device dev-disk-by\x2dlabel-ROOT.device - /dev/disk/by-label/ROOT... Sep 12 22:55:44.299111 systemd[1]: Expecting device dev-disk-by\x2dpartlabel-USR\x2dA.device - /dev/disk/by-partlabel/USR-A... Sep 12 22:55:44.299123 systemd[1]: Expecting device dev-disk-by\x2dpartuuid-7130c94a\x2d213a\x2d4e5a\x2d8e26\x2d6cce9662f132.device - /dev/disk/by-partuuid/7130c94a-213a-4e5a-8e26-6cce9662f132... Sep 12 22:55:44.299134 systemd[1]: Expecting device dev-mapper-usr.device - /dev/mapper/usr... Sep 12 22:55:44.299145 systemd[1]: Reached target cryptsetup-pre.target - Local Encrypted Volumes (Pre). Sep 12 22:55:44.299156 systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. Sep 12 22:55:44.299167 systemd[1]: Reached target paths.target - Path Units. Sep 12 22:55:44.299180 systemd[1]: Reached target slices.target - Slice Units. Sep 12 22:55:44.299190 systemd[1]: Reached target swap.target - Swaps. Sep 12 22:55:44.299202 systemd[1]: Reached target timers.target - Timer Units. Sep 12 22:55:44.304089 systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. Sep 12 22:55:44.304122 systemd[1]: Listening on iscsiuio.socket - Open-iSCSI iscsiuio Socket. Sep 12 22:55:44.304134 systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). Sep 12 22:55:44.304146 systemd[1]: Listening on systemd-journald.socket - Journal Sockets. Sep 12 22:55:44.304158 systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. Sep 12 22:55:44.304179 systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. Sep 12 22:55:44.304193 systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. Sep 12 22:55:44.304207 systemd[1]: Reached target sockets.target - Socket Units. Sep 12 22:55:44.304221 systemd[1]: Starting ignition-setup-pre.service - Ignition env setup... Sep 12 22:55:44.304235 systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... Sep 12 22:55:44.304250 systemd[1]: Finished network-cleanup.service - Network Cleanup. Sep 12 22:55:44.304264 systemd[1]: systemd-battery-check.service - Check battery level during early boot was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/class/power_supply). Sep 12 22:55:44.304284 systemd[1]: Starting systemd-fsck-usr.service... Sep 12 22:55:44.304295 systemd[1]: Starting systemd-journald.service - Journal Service... Sep 12 22:55:44.304306 systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... Sep 12 22:55:44.304317 systemd[1]: Starting systemd-vconsole-setup.service - Virtual Console Setup... Sep 12 22:55:44.304328 systemd[1]: Finished ignition-setup-pre.service - Ignition env setup. Sep 12 22:55:44.304366 systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. Sep 12 22:55:44.304377 systemd[1]: Finished systemd-fsck-usr.service. Sep 12 22:55:44.304388 systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... Sep 12 22:55:44.304441 systemd-journald[222]: Collecting audit messages is disabled. Sep 12 22:55:44.304470 systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. Sep 12 22:55:44.304482 systemd-journald[222]: Journal started Sep 12 22:55:44.304505 systemd-journald[222]: Runtime Journal (/run/log/journal/3ad7b117211d4e308fb08802441a9118) is 6M, max 48.6M, 42.5M free. Sep 12 22:55:44.312868 systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... Sep 12 22:55:44.317602 systemd[1]: Started systemd-journald.service - Journal Service. Sep 12 22:55:44.320532 systemd-modules-load[223]: Inserted module 'overlay' Sep 12 22:55:44.331481 systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... Sep 12 22:55:44.374308 systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. Sep 12 22:55:44.407670 kernel: bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this. Sep 12 22:55:44.407711 kernel: Bridge firewalling registered Sep 12 22:55:44.382673 systemd-tmpfiles[240]: /usr/lib/tmpfiles.d/var.conf:14: Duplicate line for path "/var/log", ignoring. Sep 12 22:55:44.398750 systemd-modules-load[223]: Inserted module 'br_netfilter' Sep 12 22:55:44.404074 systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. Sep 12 22:55:44.414132 systemd[1]: Finished systemd-vconsole-setup.service - Virtual Console Setup. Sep 12 22:55:44.416393 systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. Sep 12 22:55:44.435703 systemd[1]: Starting dracut-cmdline-ask.service - dracut ask for additional cmdline parameters... Sep 12 22:55:44.454126 systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... Sep 12 22:55:44.484280 systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. Sep 12 22:55:44.490894 systemd[1]: Starting systemd-resolved.service - Network Name Resolution... Sep 12 22:55:44.514563 systemd[1]: Finished dracut-cmdline-ask.service - dracut ask for additional cmdline parameters. Sep 12 22:55:44.522325 systemd[1]: Starting dracut-cmdline.service - dracut cmdline hook... Sep 12 22:55:44.585517 dracut-cmdline[263]: Using kernel command line parameters: rd.driver.pre=btrfs SYSTEMD_SULOGIN_FORCE=1 rootflags=rw mount.usrflags=ro BOOT_IMAGE=/flatcar/vmlinuz-a mount.usr=/dev/mapper/usr verity.usr=PARTUUID=7130c94a-213a-4e5a-8e26-6cce9662f132 rootflags=rw mount.usrflags=ro consoleblank=0 root=LABEL=ROOT console=ttyS0,115200 flatcar.first_boot=detected verity.usrhash=8e60d6befc710e967d67e9a1d87ced7416895090c99a765b3a00e66a62f49e40 Sep 12 22:55:44.594944 systemd-resolved[255]: Positive Trust Anchors: Sep 12 22:55:44.594966 systemd-resolved[255]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d Sep 12 22:55:44.595011 systemd-resolved[255]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test Sep 12 22:55:44.604534 systemd-resolved[255]: Defaulting to hostname 'linux'. Sep 12 22:55:44.607470 systemd[1]: Started systemd-resolved.service - Network Name Resolution. Sep 12 22:55:44.617530 systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. Sep 12 22:55:44.797360 kernel: SCSI subsystem initialized Sep 12 22:55:44.826043 kernel: Loading iSCSI transport class v2.0-870. Sep 12 22:55:44.848040 kernel: iscsi: registered transport (tcp) Sep 12 22:55:44.883745 kernel: iscsi: registered transport (qla4xxx) Sep 12 22:55:44.883827 kernel: QLogic iSCSI HBA Driver Sep 12 22:55:44.915330 systemd[1]: Starting systemd-network-generator.service - Generate network units from Kernel command line... Sep 12 22:55:44.955066 systemd[1]: Finished systemd-network-generator.service - Generate network units from Kernel command line. Sep 12 22:55:44.959838 systemd[1]: Reached target network-pre.target - Preparation for Network. Sep 12 22:55:45.066015 systemd[1]: Finished dracut-cmdline.service - dracut cmdline hook. Sep 12 22:55:45.071060 systemd[1]: Starting dracut-pre-udev.service - dracut pre-udev hook... Sep 12 22:55:45.165406 kernel: raid6: avx2x4 gen() 15225 MB/s Sep 12 22:55:45.182448 kernel: raid6: avx2x2 gen() 15975 MB/s Sep 12 22:55:45.202291 kernel: raid6: avx2x1 gen() 14915 MB/s Sep 12 22:55:45.202421 kernel: raid6: using algorithm avx2x2 gen() 15975 MB/s Sep 12 22:55:45.220509 kernel: raid6: .... xor() 12189 MB/s, rmw enabled Sep 12 22:55:45.220600 kernel: raid6: using avx2x2 recovery algorithm Sep 12 22:55:45.266462 kernel: xor: automatically using best checksumming function avx Sep 12 22:55:45.654128 kernel: Btrfs loaded, zoned=no, fsverity=no Sep 12 22:55:45.699470 systemd[1]: Finished dracut-pre-udev.service - dracut pre-udev hook. Sep 12 22:55:45.711132 systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... Sep 12 22:55:45.776498 systemd-udevd[472]: Using default interface naming scheme 'v255'. Sep 12 22:55:45.789590 systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. Sep 12 22:55:45.800006 systemd[1]: Starting dracut-pre-trigger.service - dracut pre-trigger hook... Sep 12 22:55:45.864012 dracut-pre-trigger[481]: rd.md=0: removing MD RAID activation Sep 12 22:55:45.904787 systemd[1]: Finished dracut-pre-trigger.service - dracut pre-trigger hook. Sep 12 22:55:45.907878 systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... Sep 12 22:55:46.036523 systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. Sep 12 22:55:46.050491 systemd[1]: Starting dracut-initqueue.service - dracut initqueue hook... Sep 12 22:55:46.210508 systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. Sep 12 22:55:46.210933 systemd[1]: Stopped systemd-vconsole-setup.service - Virtual Console Setup. Sep 12 22:55:46.223974 systemd[1]: Stopping systemd-vconsole-setup.service - Virtual Console Setup... Sep 12 22:55:46.229615 systemd[1]: Starting systemd-vconsole-setup.service - Virtual Console Setup... Sep 12 22:55:46.240382 systemd[1]: run-credentials-systemd\x2dvconsole\x2dsetup.service.mount: Deactivated successfully. Sep 12 22:55:46.267801 kernel: libata version 3.00 loaded. Sep 12 22:55:46.279372 kernel: cryptd: max_cpu_qlen set to 1000 Sep 12 22:55:46.341969 systemd[1]: Finished systemd-vconsole-setup.service - Virtual Console Setup. Sep 12 22:55:46.355520 kernel: virtio_blk virtio1: 4/0/0 default/read/poll queues Sep 12 22:55:46.361878 kernel: virtio_blk virtio1: [vda] 9289728 512-byte logical blocks (4.76 GB/4.43 GiB) Sep 12 22:55:46.365542 kernel: vda: vda1 vda2 vda3 vda4 vda6 vda7 vda9 Sep 12 22:55:46.416387 kernel: input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2 Sep 12 22:55:46.452427 kernel: AES CTR mode by8 optimization enabled Sep 12 22:55:46.452505 kernel: ahci 0000:00:1f.2: version 3.0 Sep 12 22:55:46.452819 kernel: ACPI: \_SB_.GSIA: Enabled at IRQ 16 Sep 12 22:55:46.462453 kernel: ahci 0000:00:1f.2: AHCI vers 0001.0000, 32 command slots, 1.5 Gbps, SATA mode Sep 12 22:55:46.462807 kernel: ahci 0000:00:1f.2: 6/6 ports implemented (port mask 0x3f) Sep 12 22:55:46.463010 kernel: ahci 0000:00:1f.2: flags: 64bit ncq only Sep 12 22:55:46.493385 kernel: scsi host0: ahci Sep 12 22:55:46.511373 kernel: scsi host1: ahci Sep 12 22:55:46.511623 kernel: scsi host2: ahci Sep 12 22:55:46.513368 kernel: scsi host3: ahci Sep 12 22:55:46.515261 kernel: scsi host4: ahci Sep 12 22:55:46.517803 kernel: scsi host5: ahci Sep 12 22:55:46.518146 kernel: ata1: SATA max UDMA/133 abar m4096@0xfebd4000 port 0xfebd4100 irq 34 lpm-pol 1 Sep 12 22:55:46.520264 kernel: ata2: SATA max UDMA/133 abar m4096@0xfebd4000 port 0xfebd4180 irq 34 lpm-pol 1 Sep 12 22:55:46.520302 kernel: ata3: SATA max UDMA/133 abar m4096@0xfebd4000 port 0xfebd4200 irq 34 lpm-pol 1 Sep 12 22:55:46.526384 kernel: ata4: SATA max UDMA/133 abar m4096@0xfebd4000 port 0xfebd4280 irq 34 lpm-pol 1 Sep 12 22:55:46.529930 kernel: ata5: SATA max UDMA/133 abar m4096@0xfebd4000 port 0xfebd4300 irq 34 lpm-pol 1 Sep 12 22:55:46.529863 systemd[1]: Found device dev-disk-by\x2dlabel-EFI\x2dSYSTEM.device - /dev/disk/by-label/EFI-SYSTEM. Sep 12 22:55:46.536678 kernel: ata6: SATA max UDMA/133 abar m4096@0xfebd4000 port 0xfebd4380 irq 34 lpm-pol 1 Sep 12 22:55:46.551149 systemd[1]: Found device dev-disk-by\x2dlabel-ROOT.device - /dev/disk/by-label/ROOT. Sep 12 22:55:46.580460 systemd[1]: Found device dev-disk-by\x2dlabel-OEM.device - /dev/disk/by-label/OEM. Sep 12 22:55:46.613788 systemd[1]: Found device dev-disk-by\x2dpartuuid-7130c94a\x2d213a\x2d4e5a\x2d8e26\x2d6cce9662f132.device - /dev/disk/by-partuuid/7130c94a-213a-4e5a-8e26-6cce9662f132. Sep 12 22:55:46.615658 systemd[1]: Found device dev-disk-by\x2dpartlabel-USR\x2dA.device - /dev/disk/by-partlabel/USR-A. Sep 12 22:55:46.623502 systemd[1]: Starting disk-uuid.service - Generate new UUID for disk GPT if necessary... Sep 12 22:55:46.658384 kernel: vda: vda1 vda2 vda3 vda4 vda6 vda7 vda9 Sep 12 22:55:46.841173 kernel: ata5: SATA link down (SStatus 0 SControl 300) Sep 12 22:55:46.841253 kernel: ata2: SATA link down (SStatus 0 SControl 300) Sep 12 22:55:46.844391 kernel: ata6: SATA link down (SStatus 0 SControl 300) Sep 12 22:55:46.849306 kernel: ata4: SATA link down (SStatus 0 SControl 300) Sep 12 22:55:46.849430 kernel: ata1: SATA link down (SStatus 0 SControl 300) Sep 12 22:55:46.855664 kernel: ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Sep 12 22:55:46.855757 kernel: ata3.00: LPM support broken, forcing max_power Sep 12 22:55:46.855774 kernel: ata3.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100 Sep 12 22:55:46.856404 kernel: ata3.00: applying bridge limits Sep 12 22:55:46.858742 kernel: ata3.00: LPM support broken, forcing max_power Sep 12 22:55:46.862087 kernel: ata3.00: configured for UDMA/100 Sep 12 22:55:46.866372 kernel: scsi 2:0:0:0: CD-ROM QEMU QEMU DVD-ROM 2.5+ PQ: 0 ANSI: 5 Sep 12 22:55:46.959619 kernel: sr 2:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray Sep 12 22:55:46.960021 kernel: cdrom: Uniform CD-ROM driver Revision: 3.20 Sep 12 22:55:46.976632 kernel: sr 2:0:0:0: Attached scsi CD-ROM sr0 Sep 12 22:55:47.377972 systemd[1]: Finished dracut-initqueue.service - dracut initqueue hook. Sep 12 22:55:47.381990 systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. Sep 12 22:55:47.386179 systemd[1]: Reached target remote-cryptsetup.target - Remote Encrypted Volumes. Sep 12 22:55:47.392966 systemd[1]: Reached target remote-fs.target - Remote File Systems. Sep 12 22:55:47.400065 systemd[1]: Starting dracut-pre-mount.service - dracut pre-mount hook... Sep 12 22:55:47.462673 systemd[1]: Finished dracut-pre-mount.service - dracut pre-mount hook. Sep 12 22:55:47.705374 kernel: vda: vda1 vda2 vda3 vda4 vda6 vda7 vda9 Sep 12 22:55:47.707868 disk-uuid[634]: The operation has completed successfully. Sep 12 22:55:47.777107 systemd[1]: disk-uuid.service: Deactivated successfully. Sep 12 22:55:47.777993 systemd[1]: Finished disk-uuid.service - Generate new UUID for disk GPT if necessary. Sep 12 22:55:47.843457 systemd[1]: Starting verity-setup.service - Verity Setup for /dev/mapper/usr... Sep 12 22:55:47.876782 sh[663]: Success Sep 12 22:55:47.910834 kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. Sep 12 22:55:47.910942 kernel: device-mapper: uevent: version 1.0.3 Sep 12 22:55:47.912230 kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev Sep 12 22:55:47.941657 kernel: device-mapper: verity: sha256 using shash "sha256-ni" Sep 12 22:55:48.016170 systemd[1]: Found device dev-mapper-usr.device - /dev/mapper/usr. Sep 12 22:55:48.028164 systemd[1]: Mounting sysusr-usr.mount - /sysusr/usr... Sep 12 22:55:48.044724 systemd[1]: Finished verity-setup.service - Verity Setup for /dev/mapper/usr. Sep 12 22:55:48.059388 kernel: BTRFS: device fsid 5d2ab445-1154-4e47-9d7e-ff4b81d84474 devid 1 transid 37 /dev/mapper/usr (253:0) scanned by mount (675) Sep 12 22:55:48.063863 kernel: BTRFS info (device dm-0): first mount of filesystem 5d2ab445-1154-4e47-9d7e-ff4b81d84474 Sep 12 22:55:48.063953 kernel: BTRFS info (device dm-0): using crc32c (crc32c-intel) checksum algorithm Sep 12 22:55:48.081426 kernel: BTRFS info (device dm-0): disabling log replay at mount time Sep 12 22:55:48.081519 kernel: BTRFS info (device dm-0): enabling free space tree Sep 12 22:55:48.085413 systemd[1]: Mounted sysusr-usr.mount - /sysusr/usr. Sep 12 22:55:48.085790 systemd[1]: Reached target initrd-usr-fs.target - Initrd /usr File System. Sep 12 22:55:48.089058 systemd[1]: afterburn-network-kargs.service - Afterburn Initrd Setup Network Kernel Arguments was skipped because no trigger condition checks were met. Sep 12 22:55:48.090277 systemd[1]: Starting ignition-setup.service - Ignition (setup)... Sep 12 22:55:48.101501 systemd[1]: Starting parse-ip-for-networkd.service - Write systemd-networkd units from cmdline... Sep 12 22:55:48.139420 kernel: BTRFS: device label OEM devid 1 transid 11 /dev/vda6 (254:6) scanned by mount (709) Sep 12 22:55:48.143864 kernel: BTRFS info (device vda6): first mount of filesystem fd5cdc72-255e-4ed2-8d25-c5e581a08827 Sep 12 22:55:48.143914 kernel: BTRFS info (device vda6): using crc32c (crc32c-intel) checksum algorithm Sep 12 22:55:48.156491 kernel: BTRFS info (device vda6): turning on async discard Sep 12 22:55:48.156581 kernel: BTRFS info (device vda6): enabling free space tree Sep 12 22:55:48.166424 kernel: BTRFS info (device vda6): last unmount of filesystem fd5cdc72-255e-4ed2-8d25-c5e581a08827 Sep 12 22:55:48.170591 systemd[1]: Finished ignition-setup.service - Ignition (setup). Sep 12 22:55:48.179796 systemd[1]: Starting ignition-fetch-offline.service - Ignition (fetch-offline)... Sep 12 22:55:48.473067 systemd[1]: Finished parse-ip-for-networkd.service - Write systemd-networkd units from cmdline. Sep 12 22:55:48.489997 systemd[1]: Starting systemd-networkd.service - Network Configuration... Sep 12 22:55:48.720086 ignition[757]: Ignition 2.22.0 Sep 12 22:55:48.720108 ignition[757]: Stage: fetch-offline Sep 12 22:55:48.723221 ignition[757]: no configs at "/usr/lib/ignition/base.d" Sep 12 22:55:48.723257 ignition[757]: no config dir at "/usr/lib/ignition/base.platform.d/qemu" Sep 12 22:55:48.723417 ignition[757]: parsed url from cmdline: "" Sep 12 22:55:48.723423 ignition[757]: no config URL provided Sep 12 22:55:48.723434 ignition[757]: reading system config file "/usr/lib/ignition/user.ign" Sep 12 22:55:48.723447 ignition[757]: no config at "/usr/lib/ignition/user.ign" Sep 12 22:55:48.723481 ignition[757]: op(1): [started] loading QEMU firmware config module Sep 12 22:55:48.723488 ignition[757]: op(1): executing: "modprobe" "qemu_fw_cfg" Sep 12 22:55:48.748708 ignition[757]: op(1): [finished] loading QEMU firmware config module Sep 12 22:55:48.749122 ignition[757]: parsing config with SHA512: 889dd2fdc154f879f3292364e9b5f28f22324e275be6e2ce80591fd33de7dffbaeb9938f45530e2962244eff298c6664b433b524d66660fb5e915a43cd74f6be Sep 12 22:55:48.761824 unknown[757]: fetched base config from "system" Sep 12 22:55:48.761839 unknown[757]: fetched user config from "qemu" Sep 12 22:55:48.762038 ignition[757]: fetch-offline: fetch-offline passed Sep 12 22:55:48.762118 ignition[757]: Ignition finished successfully Sep 12 22:55:48.771425 systemd[1]: Finished ignition-fetch-offline.service - Ignition (fetch-offline). Sep 12 22:55:48.800177 systemd-networkd[845]: lo: Link UP Sep 12 22:55:48.800192 systemd-networkd[845]: lo: Gained carrier Sep 12 22:55:48.802036 systemd-networkd[845]: Enumeration completed Sep 12 22:55:48.802473 systemd-networkd[845]: eth0: found matching network '/usr/lib/systemd/network/zz-default.network', based on potentially unpredictable interface name. Sep 12 22:55:48.802478 systemd-networkd[845]: eth0: Configuring with /usr/lib/systemd/network/zz-default.network. Sep 12 22:55:48.803280 systemd[1]: Started systemd-networkd.service - Network Configuration. Sep 12 22:55:48.804616 systemd-networkd[845]: eth0: Link UP Sep 12 22:55:48.808917 systemd[1]: Reached target network.target - Network. Sep 12 22:55:48.810408 systemd-networkd[845]: eth0: Gained carrier Sep 12 22:55:48.810428 systemd-networkd[845]: eth0: found matching network '/usr/lib/systemd/network/zz-default.network', based on potentially unpredictable interface name. Sep 12 22:55:48.813246 systemd[1]: ignition-fetch.service - Ignition (fetch) was skipped because of an unmet condition check (ConditionPathExists=!/run/ignition.json). Sep 12 22:55:48.816544 systemd[1]: Starting ignition-kargs.service - Ignition (kargs)... Sep 12 22:55:48.841505 systemd-networkd[845]: eth0: DHCPv4 address 10.0.0.63/16, gateway 10.0.0.1 acquired from 10.0.0.1 Sep 12 22:55:48.895939 ignition[856]: Ignition 2.22.0 Sep 12 22:55:48.895961 ignition[856]: Stage: kargs Sep 12 22:55:48.896190 ignition[856]: no configs at "/usr/lib/ignition/base.d" Sep 12 22:55:48.896205 ignition[856]: no config dir at "/usr/lib/ignition/base.platform.d/qemu" Sep 12 22:55:48.897272 ignition[856]: kargs: kargs passed Sep 12 22:55:48.897332 ignition[856]: Ignition finished successfully Sep 12 22:55:48.911473 systemd[1]: Finished ignition-kargs.service - Ignition (kargs). Sep 12 22:55:48.917917 systemd[1]: Starting ignition-disks.service - Ignition (disks)... Sep 12 22:55:49.021969 ignition[865]: Ignition 2.22.0 Sep 12 22:55:49.021985 ignition[865]: Stage: disks Sep 12 22:55:49.022179 ignition[865]: no configs at "/usr/lib/ignition/base.d" Sep 12 22:55:49.022192 ignition[865]: no config dir at "/usr/lib/ignition/base.platform.d/qemu" Sep 12 22:55:49.034473 ignition[865]: disks: disks passed Sep 12 22:55:49.035320 ignition[865]: Ignition finished successfully Sep 12 22:55:49.047117 systemd[1]: Finished ignition-disks.service - Ignition (disks). Sep 12 22:55:49.048919 systemd[1]: Reached target initrd-root-device.target - Initrd Root Device. Sep 12 22:55:49.066276 systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. Sep 12 22:55:49.076558 systemd[1]: Reached target local-fs.target - Local File Systems. Sep 12 22:55:49.078435 systemd[1]: Reached target sysinit.target - System Initialization. Sep 12 22:55:49.081544 systemd[1]: Reached target basic.target - Basic System. Sep 12 22:55:49.096572 systemd[1]: Starting systemd-fsck-root.service - File System Check on /dev/disk/by-label/ROOT... Sep 12 22:55:49.167943 systemd-fsck[874]: ROOT: clean, 15/553520 files, 52789/553472 blocks Sep 12 22:55:49.184863 systemd[1]: Finished systemd-fsck-root.service - File System Check on /dev/disk/by-label/ROOT. Sep 12 22:55:49.190883 systemd[1]: Mounting sysroot.mount - /sysroot... Sep 12 22:55:49.578276 kernel: EXT4-fs (vda9): mounted filesystem d027afc5-396a-49bf-a5be-60ddd42cb089 r/w with ordered data mode. Quota mode: none. Sep 12 22:55:49.577115 systemd[1]: Mounted sysroot.mount - /sysroot. Sep 12 22:55:49.580237 systemd[1]: Reached target initrd-root-fs.target - Initrd Root File System. Sep 12 22:55:49.587470 systemd[1]: Mounting sysroot-oem.mount - /sysroot/oem... Sep 12 22:55:49.626384 systemd[1]: Mounting sysroot-usr.mount - /sysroot/usr... Sep 12 22:55:49.631617 systemd[1]: flatcar-metadata-hostname.service - Flatcar Metadata Hostname Agent was skipped because no trigger condition checks were met. Sep 12 22:55:49.631690 systemd[1]: ignition-remount-sysroot.service - Remount /sysroot read-write for Ignition was skipped because of an unmet condition check (ConditionPathIsReadWrite=!/sysroot). Sep 12 22:55:49.631728 systemd[1]: Reached target ignition-diskful.target - Ignition Boot Disk Setup. Sep 12 22:55:49.658870 kernel: BTRFS: device label OEM devid 1 transid 11 /dev/vda6 (254:6) scanned by mount (882) Sep 12 22:55:49.673310 kernel: BTRFS info (device vda6): first mount of filesystem fd5cdc72-255e-4ed2-8d25-c5e581a08827 Sep 12 22:55:49.673426 kernel: BTRFS info (device vda6): using crc32c (crc32c-intel) checksum algorithm Sep 12 22:55:49.707741 systemd[1]: Mounted sysroot-usr.mount - /sysroot/usr. Sep 12 22:55:49.722932 systemd[1]: Starting initrd-setup-root.service - Root filesystem setup... Sep 12 22:55:49.732686 kernel: BTRFS info (device vda6): turning on async discard Sep 12 22:55:49.732738 kernel: BTRFS info (device vda6): enabling free space tree Sep 12 22:55:49.742504 systemd[1]: Mounted sysroot-oem.mount - /sysroot/oem. Sep 12 22:55:49.881591 initrd-setup-root[906]: cut: /sysroot/etc/passwd: No such file or directory Sep 12 22:55:49.893991 initrd-setup-root[913]: cut: /sysroot/etc/group: No such file or directory Sep 12 22:55:49.909855 initrd-setup-root[920]: cut: /sysroot/etc/shadow: No such file or directory Sep 12 22:55:49.926878 initrd-setup-root[927]: cut: /sysroot/etc/gshadow: No such file or directory Sep 12 22:55:50.235800 systemd[1]: Finished initrd-setup-root.service - Root filesystem setup. Sep 12 22:55:50.256565 systemd[1]: Starting ignition-mount.service - Ignition (mount)... Sep 12 22:55:50.299613 systemd[1]: Starting sysroot-boot.service - /sysroot/boot... Sep 12 22:55:50.316632 systemd[1]: sysroot-oem.mount: Deactivated successfully. Sep 12 22:55:50.324093 kernel: BTRFS info (device vda6): last unmount of filesystem fd5cdc72-255e-4ed2-8d25-c5e581a08827 Sep 12 22:55:50.453918 systemd[1]: Finished sysroot-boot.service - /sysroot/boot. Sep 12 22:55:50.496760 ignition[996]: INFO : Ignition 2.22.0 Sep 12 22:55:50.496760 ignition[996]: INFO : Stage: mount Sep 12 22:55:50.505394 ignition[996]: INFO : no configs at "/usr/lib/ignition/base.d" Sep 12 22:55:50.505394 ignition[996]: INFO : no config dir at "/usr/lib/ignition/base.platform.d/qemu" Sep 12 22:55:50.505394 ignition[996]: INFO : mount: mount passed Sep 12 22:55:50.505394 ignition[996]: INFO : Ignition finished successfully Sep 12 22:55:50.512288 systemd[1]: Finished ignition-mount.service - Ignition (mount). Sep 12 22:55:50.530490 systemd[1]: Starting ignition-files.service - Ignition (files)... Sep 12 22:55:50.594486 systemd[1]: Mounting sysroot-oem.mount - /sysroot/oem... Sep 12 22:55:50.650517 kernel: BTRFS: device label OEM devid 1 transid 11 /dev/vda6 (254:6) scanned by mount (1008) Sep 12 22:55:50.655481 kernel: BTRFS info (device vda6): first mount of filesystem fd5cdc72-255e-4ed2-8d25-c5e581a08827 Sep 12 22:55:50.655522 kernel: BTRFS info (device vda6): using crc32c (crc32c-intel) checksum algorithm Sep 12 22:55:50.665844 kernel: BTRFS info (device vda6): turning on async discard Sep 12 22:55:50.665918 kernel: BTRFS info (device vda6): enabling free space tree Sep 12 22:55:50.671463 systemd[1]: Mounted sysroot-oem.mount - /sysroot/oem. Sep 12 22:55:50.683206 systemd-networkd[845]: eth0: Gained IPv6LL Sep 12 22:55:50.818598 ignition[1025]: INFO : Ignition 2.22.0 Sep 12 22:55:50.818598 ignition[1025]: INFO : Stage: files Sep 12 22:55:50.822538 ignition[1025]: INFO : no configs at "/usr/lib/ignition/base.d" Sep 12 22:55:50.822538 ignition[1025]: INFO : no config dir at "/usr/lib/ignition/base.platform.d/qemu" Sep 12 22:55:50.822538 ignition[1025]: DEBUG : files: compiled without relabeling support, skipping Sep 12 22:55:50.830577 ignition[1025]: INFO : files: ensureUsers: op(1): [started] creating or modifying user "core" Sep 12 22:55:50.830577 ignition[1025]: DEBUG : files: ensureUsers: op(1): executing: "usermod" "--root" "/sysroot" "core" Sep 12 22:55:50.830577 ignition[1025]: INFO : files: ensureUsers: op(1): [finished] creating or modifying user "core" Sep 12 22:55:50.830577 ignition[1025]: INFO : files: ensureUsers: op(2): [started] adding ssh keys to user "core" Sep 12 22:55:50.840813 ignition[1025]: INFO : files: ensureUsers: op(2): [finished] adding ssh keys to user "core" Sep 12 22:55:50.831874 unknown[1025]: wrote ssh authorized keys file for user: core Sep 12 22:55:50.844741 ignition[1025]: INFO : files: createFilesystemsFiles: createFiles: op(3): [started] writing file "/sysroot/etc/flatcar/update.conf" Sep 12 22:55:50.847694 ignition[1025]: INFO : files: createFilesystemsFiles: createFiles: op(3): [finished] writing file "/sysroot/etc/flatcar/update.conf" Sep 12 22:55:50.847694 ignition[1025]: INFO : files: op(4): [started] processing unit "etcd-member.service" Sep 12 22:55:50.847694 ignition[1025]: INFO : files: op(4): op(5): [started] writing systemd drop-in "20-clct-etcd-member.conf" at "/sysroot/etc/systemd/system/etcd-member.service.d/20-clct-etcd-member.conf" Sep 12 22:55:50.857636 ignition[1025]: INFO : files: op(4): op(5): [finished] writing systemd drop-in "20-clct-etcd-member.conf" at "/sysroot/etc/systemd/system/etcd-member.service.d/20-clct-etcd-member.conf" Sep 12 22:55:50.857636 ignition[1025]: INFO : files: op(4): [finished] processing unit "etcd-member.service" Sep 12 22:55:50.857636 ignition[1025]: INFO : files: op(6): [started] processing unit "coreos-metadata.service" Sep 12 22:55:50.857636 ignition[1025]: INFO : files: op(6): op(7): [started] writing unit "coreos-metadata.service" at "/sysroot/etc/systemd/system/coreos-metadata.service" Sep 12 22:55:50.857636 ignition[1025]: INFO : files: op(6): op(7): [finished] writing unit "coreos-metadata.service" at "/sysroot/etc/systemd/system/coreos-metadata.service" Sep 12 22:55:50.857636 ignition[1025]: INFO : files: op(6): [finished] processing unit "coreos-metadata.service" Sep 12 22:55:50.857636 ignition[1025]: INFO : files: op(8): [started] setting preset to disabled for "coreos-metadata.service" Sep 12 22:55:50.950149 ignition[1025]: INFO : files: op(8): op(9): [started] removing enablement symlink(s) for "coreos-metadata.service" Sep 12 22:55:50.962304 ignition[1025]: INFO : files: op(8): op(9): [finished] removing enablement symlink(s) for "coreos-metadata.service" Sep 12 22:55:50.974004 ignition[1025]: INFO : files: op(8): [finished] setting preset to disabled for "coreos-metadata.service" Sep 12 22:55:50.974004 ignition[1025]: INFO : files: op(a): [started] setting preset to enabled for "etcd-member.service" Sep 12 22:55:50.974004 ignition[1025]: INFO : files: op(a): [finished] setting preset to enabled for "etcd-member.service" Sep 12 22:55:50.974004 ignition[1025]: INFO : files: createResultFile: createFiles: op(b): [started] writing file "/sysroot/etc/.ignition-result.json" Sep 12 22:55:50.974004 ignition[1025]: INFO : files: createResultFile: createFiles: op(b): [finished] writing file "/sysroot/etc/.ignition-result.json" Sep 12 22:55:50.974004 ignition[1025]: INFO : files: files passed Sep 12 22:55:50.974004 ignition[1025]: INFO : Ignition finished successfully Sep 12 22:55:50.973175 systemd[1]: Finished ignition-files.service - Ignition (files). Sep 12 22:55:50.997881 systemd[1]: Starting ignition-quench.service - Ignition (record completion)... Sep 12 22:55:51.005144 systemd[1]: Starting initrd-setup-root-after-ignition.service - Root filesystem completion... Sep 12 22:55:51.045632 systemd[1]: ignition-quench.service: Deactivated successfully. Sep 12 22:55:51.054659 initrd-setup-root-after-ignition[1053]: grep: /sysroot/oem/oem-release: No such file or directory Sep 12 22:55:51.045800 systemd[1]: Finished ignition-quench.service - Ignition (record completion). Sep 12 22:55:51.068012 initrd-setup-root-after-ignition[1055]: grep: /sysroot/etc/flatcar/enabled-sysext.conf: No such file or directory Sep 12 22:55:51.068012 initrd-setup-root-after-ignition[1055]: grep: /sysroot/usr/share/flatcar/enabled-sysext.conf: No such file or directory Sep 12 22:55:51.084562 initrd-setup-root-after-ignition[1059]: grep: /sysroot/etc/flatcar/enabled-sysext.conf: No such file or directory Sep 12 22:55:51.078308 systemd[1]: Finished initrd-setup-root-after-ignition.service - Root filesystem completion. Sep 12 22:55:51.103770 systemd[1]: Reached target ignition-complete.target - Ignition Complete. Sep 12 22:55:51.113266 systemd[1]: Starting initrd-parse-etc.service - Mountpoints Configured in the Real Root... Sep 12 22:55:51.273585 systemd[1]: initrd-parse-etc.service: Deactivated successfully. Sep 12 22:55:51.275689 systemd[1]: Finished initrd-parse-etc.service - Mountpoints Configured in the Real Root. Sep 12 22:55:51.287959 systemd[1]: Reached target initrd-fs.target - Initrd File Systems. Sep 12 22:55:51.298321 systemd[1]: Reached target initrd.target - Initrd Default Target. Sep 12 22:55:51.299875 systemd[1]: dracut-mount.service - dracut mount hook was skipped because no trigger condition checks were met. Sep 12 22:55:51.313354 systemd[1]: Starting dracut-pre-pivot.service - dracut pre-pivot and cleanup hook... Sep 12 22:55:51.366025 systemd[1]: Finished dracut-pre-pivot.service - dracut pre-pivot and cleanup hook. Sep 12 22:55:51.382327 systemd[1]: Starting initrd-cleanup.service - Cleaning Up and Shutting Down Daemons... Sep 12 22:55:51.464963 systemd[1]: Stopped target nss-lookup.target - Host and Network Name Lookups. Sep 12 22:55:51.469783 systemd[1]: Stopped target remote-cryptsetup.target - Remote Encrypted Volumes. Sep 12 22:55:51.470275 systemd[1]: Stopped target timers.target - Timer Units. Sep 12 22:55:51.474627 systemd[1]: dracut-pre-pivot.service: Deactivated successfully. Sep 12 22:55:51.474819 systemd[1]: Stopped dracut-pre-pivot.service - dracut pre-pivot and cleanup hook. Sep 12 22:55:51.505773 systemd[1]: Stopped target initrd.target - Initrd Default Target. Sep 12 22:55:51.511452 systemd[1]: Stopped target basic.target - Basic System. Sep 12 22:55:51.520732 systemd[1]: Stopped target ignition-complete.target - Ignition Complete. Sep 12 22:55:51.522307 systemd[1]: Stopped target ignition-diskful.target - Ignition Boot Disk Setup. Sep 12 22:55:51.528460 systemd[1]: Stopped target initrd-root-device.target - Initrd Root Device. Sep 12 22:55:51.571728 systemd[1]: Stopped target initrd-usr-fs.target - Initrd /usr File System. Sep 12 22:55:51.576788 systemd[1]: Stopped target remote-fs.target - Remote File Systems. Sep 12 22:55:51.601031 systemd[1]: Stopped target remote-fs-pre.target - Preparation for Remote File Systems. Sep 12 22:55:51.604296 systemd[1]: Stopped target sysinit.target - System Initialization. Sep 12 22:55:51.604440 systemd[1]: Stopped target local-fs.target - Local File Systems. Sep 12 22:55:51.604547 systemd[1]: Stopped target swap.target - Swaps. Sep 12 22:55:51.604632 systemd[1]: dracut-pre-mount.service: Deactivated successfully. Sep 12 22:55:51.604782 systemd[1]: Stopped dracut-pre-mount.service - dracut pre-mount hook. Sep 12 22:55:51.605027 systemd[1]: Stopped target cryptsetup.target - Local Encrypted Volumes. Sep 12 22:55:51.605157 systemd[1]: Stopped target cryptsetup-pre.target - Local Encrypted Volumes (Pre). Sep 12 22:55:51.605230 systemd[1]: clevis-luks-askpass.path: Deactivated successfully. Sep 12 22:55:51.608568 systemd[1]: Stopped clevis-luks-askpass.path - Forward Password Requests to Clevis Directory Watch. Sep 12 22:55:51.629709 systemd[1]: dracut-initqueue.service: Deactivated successfully. Sep 12 22:55:51.629887 systemd[1]: Stopped dracut-initqueue.service - dracut initqueue hook. Sep 12 22:55:51.630156 systemd[1]: ignition-fetch-offline.service: Deactivated successfully. Sep 12 22:55:51.630276 systemd[1]: Stopped ignition-fetch-offline.service - Ignition (fetch-offline). Sep 12 22:55:51.630525 systemd[1]: Stopped target paths.target - Path Units. Sep 12 22:55:51.630597 systemd[1]: systemd-ask-password-console.path: Deactivated successfully. Sep 12 22:55:51.635433 systemd[1]: Stopped systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. Sep 12 22:55:51.659568 systemd[1]: Stopped target slices.target - Slice Units. Sep 12 22:55:51.677403 systemd[1]: Stopped target sockets.target - Socket Units. Sep 12 22:55:51.677553 systemd[1]: iscsid.socket: Deactivated successfully. Sep 12 22:55:51.677673 systemd[1]: Closed iscsid.socket - Open-iSCSI iscsid Socket. Sep 12 22:55:51.677804 systemd[1]: iscsiuio.socket: Deactivated successfully. Sep 12 22:55:51.677894 systemd[1]: Closed iscsiuio.socket - Open-iSCSI iscsiuio Socket. Sep 12 22:55:51.678057 systemd[1]: initrd-setup-root-after-ignition.service: Deactivated successfully. Sep 12 22:55:51.678202 systemd[1]: Stopped initrd-setup-root-after-ignition.service - Root filesystem completion. Sep 12 22:55:51.678386 systemd[1]: ignition-files.service: Deactivated successfully. Sep 12 22:55:51.678502 systemd[1]: Stopped ignition-files.service - Ignition (files). Sep 12 22:55:51.682310 systemd[1]: Stopping ignition-mount.service - Ignition (mount)... Sep 12 22:55:51.720686 systemd[1]: Stopping sysroot-boot.service - /sysroot/boot... Sep 12 22:55:51.803349 systemd[1]: systemd-udev-trigger.service: Deactivated successfully. Sep 12 22:55:51.803689 systemd[1]: Stopped systemd-udev-trigger.service - Coldplug All udev Devices. Sep 12 22:55:51.804245 systemd[1]: dracut-pre-trigger.service: Deactivated successfully. Sep 12 22:55:51.804470 systemd[1]: Stopped dracut-pre-trigger.service - dracut pre-trigger hook. Sep 12 22:55:51.827841 systemd[1]: initrd-cleanup.service: Deactivated successfully. Sep 12 22:55:51.830268 systemd[1]: Finished initrd-cleanup.service - Cleaning Up and Shutting Down Daemons. Sep 12 22:55:51.901117 systemd[1]: sysroot-boot.mount: Deactivated successfully. Sep 12 22:55:51.920720 systemd[1]: sysroot-boot.service: Deactivated successfully. Sep 12 22:55:51.920893 systemd[1]: Stopped sysroot-boot.service - /sysroot/boot. Sep 12 22:55:51.936723 ignition[1080]: INFO : Ignition 2.22.0 Sep 12 22:55:51.936723 ignition[1080]: INFO : Stage: umount Sep 12 22:55:51.936723 ignition[1080]: INFO : no configs at "/usr/lib/ignition/base.d" Sep 12 22:55:51.936723 ignition[1080]: INFO : no config dir at "/usr/lib/ignition/base.platform.d/qemu" Sep 12 22:55:51.936723 ignition[1080]: INFO : umount: umount passed Sep 12 22:55:51.936723 ignition[1080]: INFO : Ignition finished successfully Sep 12 22:55:51.938478 systemd[1]: ignition-mount.service: Deactivated successfully. Sep 12 22:55:51.938658 systemd[1]: Stopped ignition-mount.service - Ignition (mount). Sep 12 22:55:51.941802 systemd[1]: Stopped target network.target - Network. Sep 12 22:55:51.952174 systemd[1]: ignition-disks.service: Deactivated successfully. Sep 12 22:55:51.952312 systemd[1]: Stopped ignition-disks.service - Ignition (disks). Sep 12 22:55:51.963923 systemd[1]: ignition-kargs.service: Deactivated successfully. Sep 12 22:55:51.964042 systemd[1]: Stopped ignition-kargs.service - Ignition (kargs). Sep 12 22:55:51.964207 systemd[1]: ignition-setup.service: Deactivated successfully. Sep 12 22:55:51.964283 systemd[1]: Stopped ignition-setup.service - Ignition (setup). Sep 12 22:55:51.964395 systemd[1]: ignition-setup-pre.service: Deactivated successfully. Sep 12 22:55:51.964458 systemd[1]: Stopped ignition-setup-pre.service - Ignition env setup. Sep 12 22:55:51.965814 systemd[1]: initrd-setup-root.service: Deactivated successfully. Sep 12 22:55:51.965884 systemd[1]: Stopped initrd-setup-root.service - Root filesystem setup. Sep 12 22:55:51.966359 systemd[1]: Stopping systemd-networkd.service - Network Configuration... Sep 12 22:55:51.966851 systemd[1]: Stopping systemd-resolved.service - Network Name Resolution... Sep 12 22:55:52.018633 systemd[1]: systemd-resolved.service: Deactivated successfully. Sep 12 22:55:52.018860 systemd[1]: Stopped systemd-resolved.service - Network Name Resolution. Sep 12 22:55:52.086158 systemd[1]: run-credentials-systemd\x2dresolved.service.mount: Deactivated successfully. Sep 12 22:55:52.086571 systemd[1]: systemd-networkd.service: Deactivated successfully. Sep 12 22:55:52.086757 systemd[1]: Stopped systemd-networkd.service - Network Configuration. Sep 12 22:55:52.111160 systemd[1]: run-credentials-systemd\x2dnetworkd.service.mount: Deactivated successfully. Sep 12 22:55:52.130258 systemd[1]: Stopped target network-pre.target - Preparation for Network. Sep 12 22:55:52.137800 systemd[1]: systemd-networkd.socket: Deactivated successfully. Sep 12 22:55:52.137885 systemd[1]: Closed systemd-networkd.socket - Network Service Netlink Socket. Sep 12 22:55:52.178388 systemd[1]: Stopping network-cleanup.service - Network Cleanup... Sep 12 22:55:52.179661 systemd[1]: parse-ip-for-networkd.service: Deactivated successfully. Sep 12 22:55:52.179772 systemd[1]: Stopped parse-ip-for-networkd.service - Write systemd-networkd units from cmdline. Sep 12 22:55:52.188436 systemd[1]: systemd-sysctl.service: Deactivated successfully. Sep 12 22:55:52.188538 systemd[1]: Stopped systemd-sysctl.service - Apply Kernel Variables. Sep 12 22:55:52.192074 systemd[1]: systemd-modules-load.service: Deactivated successfully. Sep 12 22:55:52.192163 systemd[1]: Stopped systemd-modules-load.service - Load Kernel Modules. Sep 12 22:55:52.221856 systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully. Sep 12 22:55:52.221967 systemd[1]: Stopped systemd-tmpfiles-setup.service - Create System Files and Directories. Sep 12 22:55:52.286458 systemd[1]: Stopping systemd-udevd.service - Rule-based Manager for Device Events and Files... Sep 12 22:55:52.310467 systemd[1]: run-credentials-systemd\x2dsysctl.service.mount: Deactivated successfully. Sep 12 22:55:52.310577 systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount: Deactivated successfully. Sep 12 22:55:52.351327 systemd[1]: systemd-udevd.service: Deactivated successfully. Sep 12 22:55:52.355064 systemd[1]: Stopped systemd-udevd.service - Rule-based Manager for Device Events and Files. Sep 12 22:55:52.379718 systemd[1]: network-cleanup.service: Deactivated successfully. Sep 12 22:55:52.387607 systemd[1]: Stopped network-cleanup.service - Network Cleanup. Sep 12 22:55:52.407443 systemd[1]: systemd-udevd-control.socket: Deactivated successfully. Sep 12 22:55:52.407560 systemd[1]: Closed systemd-udevd-control.socket - udev Control Socket. Sep 12 22:55:52.410272 systemd[1]: systemd-udevd-kernel.socket: Deactivated successfully. Sep 12 22:55:52.410361 systemd[1]: Closed systemd-udevd-kernel.socket - udev Kernel Socket. Sep 12 22:55:52.415735 systemd[1]: dracut-pre-udev.service: Deactivated successfully. Sep 12 22:55:52.415863 systemd[1]: Stopped dracut-pre-udev.service - dracut pre-udev hook. Sep 12 22:55:52.436889 systemd[1]: dracut-cmdline.service: Deactivated successfully. Sep 12 22:55:52.437028 systemd[1]: Stopped dracut-cmdline.service - dracut cmdline hook. Sep 12 22:55:52.444311 systemd[1]: dracut-cmdline-ask.service: Deactivated successfully. Sep 12 22:55:52.444469 systemd[1]: Stopped dracut-cmdline-ask.service - dracut ask for additional cmdline parameters. Sep 12 22:55:52.458273 systemd[1]: Starting initrd-udevadm-cleanup-db.service - Cleanup udev Database... Sep 12 22:55:52.467067 systemd[1]: systemd-network-generator.service: Deactivated successfully. Sep 12 22:55:52.467643 systemd[1]: Stopped systemd-network-generator.service - Generate network units from Kernel command line. Sep 12 22:55:52.478303 systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully. Sep 12 22:55:52.478430 systemd[1]: Stopped systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. Sep 12 22:55:52.492483 systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully. Sep 12 22:55:52.492580 systemd[1]: Stopped systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. Sep 12 22:55:52.521903 systemd[1]: kmod-static-nodes.service: Deactivated successfully. Sep 12 22:55:52.522008 systemd[1]: Stopped kmod-static-nodes.service - Create List of Static Device Nodes. Sep 12 22:55:52.529586 systemd[1]: systemd-vconsole-setup.service: Deactivated successfully. Sep 12 22:55:52.530904 systemd[1]: Stopped systemd-vconsole-setup.service - Virtual Console Setup. Sep 12 22:55:52.539703 systemd[1]: run-credentials-systemd\x2dnetwork\x2dgenerator.service.mount: Deactivated successfully. Sep 12 22:55:52.540748 systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev\x2dearly.service.mount: Deactivated successfully. Sep 12 22:55:52.543525 systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev.service.mount: Deactivated successfully. Sep 12 22:55:52.543774 systemd[1]: run-credentials-systemd\x2dvconsole\x2dsetup.service.mount: Deactivated successfully. Sep 12 22:55:52.544520 systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully. Sep 12 22:55:52.544660 systemd[1]: Finished initrd-udevadm-cleanup-db.service - Cleanup udev Database. Sep 12 22:55:52.567250 systemd[1]: Reached target initrd-switch-root.target - Switch Root. Sep 12 22:55:52.573314 systemd[1]: Starting initrd-switch-root.service - Switch Root... Sep 12 22:55:52.626979 systemd[1]: Switching root. Sep 12 22:55:52.698775 systemd-journald[222]: Journal stopped Sep 12 22:55:55.678917 systemd-journald[222]: Received SIGTERM from PID 1 (systemd). Sep 12 22:55:55.680083 kernel: SELinux: policy capability network_peer_controls=1 Sep 12 22:55:55.680117 kernel: SELinux: policy capability open_perms=1 Sep 12 22:55:55.680146 kernel: SELinux: policy capability extended_socket_class=1 Sep 12 22:55:55.680163 kernel: SELinux: policy capability always_check_network=0 Sep 12 22:55:55.680180 kernel: SELinux: policy capability cgroup_seclabel=1 Sep 12 22:55:55.680204 kernel: SELinux: policy capability nnp_nosuid_transition=1 Sep 12 22:55:55.680229 kernel: SELinux: policy capability genfs_seclabel_symlinks=0 Sep 12 22:55:55.680245 kernel: SELinux: policy capability ioctl_skip_cloexec=0 Sep 12 22:55:55.680278 kernel: SELinux: policy capability userspace_initial_context=0 Sep 12 22:55:55.680295 kernel: audit: type=1403 audit(1757717752.983:2): auid=4294967295 ses=4294967295 lsm=selinux res=1 Sep 12 22:55:55.680325 systemd[1]: Successfully loaded SELinux policy in 131.393ms. Sep 12 22:55:55.680389 systemd[1]: Relabeled /dev/, /dev/shm/, /run/ in 19.700ms. Sep 12 22:55:55.680418 systemd[1]: systemd 256.8 running in system mode (+PAM +AUDIT +SELINUX -APPARMOR +IMA +SMACK +SECCOMP -GCRYPT -GNUTLS +OPENSSL -ACL +BLKID +CURL +ELFUTILS -FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK -XKBCOMMON +UTMP -SYSVINIT +LIBARCHIVE) Sep 12 22:55:55.680447 systemd[1]: Detected virtualization kvm. Sep 12 22:55:55.680487 systemd[1]: Detected architecture x86-64. Sep 12 22:55:55.680520 systemd[1]: Detected first boot. Sep 12 22:55:55.680551 systemd[1]: Initializing machine ID from VM UUID. Sep 12 22:55:55.680571 zram_generator::config[1125]: No configuration found. Sep 12 22:55:55.680590 kernel: Guest personality initialized and is inactive Sep 12 22:55:55.680628 kernel: VMCI host device registered (name=vmci, major=10, minor=125) Sep 12 22:55:55.680653 kernel: Initialized host personality Sep 12 22:55:55.680680 kernel: NET: Registered PF_VSOCK protocol family Sep 12 22:55:55.680725 systemd[1]: Populated /etc with preset unit settings. Sep 12 22:55:55.680748 systemd[1]: run-credentials-systemd\x2djournald.service.mount: Deactivated successfully. Sep 12 22:55:55.680766 systemd[1]: initrd-switch-root.service: Deactivated successfully. Sep 12 22:55:55.680793 systemd[1]: Stopped initrd-switch-root.service - Switch Root. Sep 12 22:55:55.680828 systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. Sep 12 22:55:55.680857 systemd[1]: Created slice system-addon\x2dconfig.slice - Slice /system/addon-config. Sep 12 22:55:55.680898 systemd[1]: Created slice system-addon\x2drun.slice - Slice /system/addon-run. Sep 12 22:55:55.684845 systemd[1]: Created slice system-getty.slice - Slice /system/getty. Sep 12 22:55:55.684890 systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. Sep 12 22:55:55.684932 systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. Sep 12 22:55:55.684956 systemd[1]: Created slice system-system\x2dcloudinit.slice - Slice /system/system-cloudinit. Sep 12 22:55:55.684983 systemd[1]: Created slice system-systemd\x2dfsck.slice - Slice /system/systemd-fsck. Sep 12 22:55:55.684999 systemd[1]: Created slice user.slice - User and Session Slice. Sep 12 22:55:55.685027 systemd[1]: Started clevis-luks-askpass.path - Forward Password Requests to Clevis Directory Watch. Sep 12 22:55:55.685053 systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. Sep 12 22:55:55.685082 systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. Sep 12 22:55:55.685122 systemd[1]: Set up automount boot.automount - Boot partition Automount Point. Sep 12 22:55:55.685170 systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. Sep 12 22:55:55.685196 systemd[1]: Expecting device dev-disk-by\x2dlabel-OEM.device - /dev/disk/by-label/OEM... Sep 12 22:55:55.685240 systemd[1]: Expecting device dev-ttyS0.device - /dev/ttyS0... Sep 12 22:55:55.685264 systemd[1]: Reached target cryptsetup-pre.target - Local Encrypted Volumes (Pre). Sep 12 22:55:55.685301 systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. Sep 12 22:55:55.685368 systemd[1]: Stopped target initrd-switch-root.target - Switch Root. Sep 12 22:55:55.685393 systemd[1]: Stopped target initrd-fs.target - Initrd File Systems. Sep 12 22:55:55.685417 systemd[1]: Stopped target initrd-root-fs.target - Initrd Root File System. Sep 12 22:55:55.685448 systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. Sep 12 22:55:55.685478 systemd[1]: Reached target remote-cryptsetup.target - Remote Encrypted Volumes. Sep 12 22:55:55.685502 systemd[1]: Reached target remote-fs.target - Remote File Systems. Sep 12 22:55:55.685532 systemd[1]: Reached target slices.target - Slice Units. Sep 12 22:55:55.685564 systemd[1]: Reached target swap.target - Swaps. Sep 12 22:55:55.685605 systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. Sep 12 22:55:55.685640 systemd[1]: Listening on systemd-coredump.socket - Process Core Dump Socket. Sep 12 22:55:55.685666 systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. Sep 12 22:55:55.685693 systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. Sep 12 22:55:55.685730 systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. Sep 12 22:55:55.685749 systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. Sep 12 22:55:55.685773 systemd[1]: Listening on systemd-userdbd.socket - User Database Manager Socket. Sep 12 22:55:55.685794 systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... Sep 12 22:55:55.685817 systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... Sep 12 22:55:55.685841 systemd[1]: Mounting media.mount - External Media Directory... Sep 12 22:55:55.685866 systemd[1]: proc-xen.mount - /proc/xen was skipped because of an unmet condition check (ConditionVirtualization=xen). Sep 12 22:55:55.685901 systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... Sep 12 22:55:55.685919 systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... Sep 12 22:55:55.685940 systemd[1]: Mounting tmp.mount - Temporary Directory /tmp... Sep 12 22:55:55.685958 systemd[1]: var-lib-machines.mount - Virtual Machine and Container Storage (Compatibility) was skipped because of an unmet condition check (ConditionPathExists=/var/lib/machines.raw). Sep 12 22:55:55.688225 systemd[1]: Reached target machines.target - Containers. Sep 12 22:55:55.688287 systemd[1]: Starting flatcar-tmpfiles.service - Create missing system files... Sep 12 22:55:55.688318 systemd[1]: ignition-delete-config.service - Ignition (delete config) was skipped because no trigger condition checks were met. Sep 12 22:55:55.688358 systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... Sep 12 22:55:55.688385 systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... Sep 12 22:55:55.688402 systemd[1]: Starting modprobe@dm_mod.service - Load Kernel Module dm_mod... Sep 12 22:55:55.688418 systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... Sep 12 22:55:55.688434 systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... Sep 12 22:55:55.688449 systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... Sep 12 22:55:55.688465 systemd[1]: Starting modprobe@loop.service - Load Kernel Module loop... Sep 12 22:55:55.688481 systemd[1]: setup-nsswitch.service - Create /etc/nsswitch.conf was skipped because of an unmet condition check (ConditionPathExists=!/etc/nsswitch.conf). Sep 12 22:55:55.688497 systemd[1]: systemd-fsck-root.service: Deactivated successfully. Sep 12 22:55:55.688518 systemd[1]: Stopped systemd-fsck-root.service - File System Check on Root Device. Sep 12 22:55:55.688534 systemd[1]: systemd-fsck-usr.service: Deactivated successfully. Sep 12 22:55:55.688549 systemd[1]: Stopped systemd-fsck-usr.service. Sep 12 22:55:55.688569 systemd[1]: systemd-hibernate-clear.service - Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67). Sep 12 22:55:55.688595 systemd[1]: Starting systemd-journald.service - Journal Service... Sep 12 22:55:55.688614 systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... Sep 12 22:55:55.688636 systemd[1]: Starting systemd-network-generator.service - Generate network units from Kernel command line... Sep 12 22:55:55.688657 systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... Sep 12 22:55:55.688679 systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... Sep 12 22:55:55.688705 systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... Sep 12 22:55:55.688726 systemd[1]: verity-setup.service: Deactivated successfully. Sep 12 22:55:55.688754 systemd[1]: Stopped verity-setup.service. Sep 12 22:55:55.688778 systemd[1]: xenserver-pv-version.service - Set fake PV driver version for XenServer was skipped because of an unmet condition check (ConditionVirtualization=xen). Sep 12 22:55:55.688801 systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. Sep 12 22:55:55.688821 systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. Sep 12 22:55:55.688842 systemd[1]: Mounted media.mount - External Media Directory. Sep 12 22:55:55.688859 systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. Sep 12 22:55:55.688875 systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. Sep 12 22:55:55.688899 systemd[1]: Mounted tmp.mount - Temporary Directory /tmp. Sep 12 22:55:55.688926 systemd[1]: Finished flatcar-tmpfiles.service - Create missing system files. Sep 12 22:55:55.688950 systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. Sep 12 22:55:55.688977 systemd[1]: modprobe@configfs.service: Deactivated successfully. Sep 12 22:55:55.688997 systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. Sep 12 22:55:55.689014 systemd[1]: modprobe@dm_mod.service: Deactivated successfully. Sep 12 22:55:55.689031 systemd[1]: Finished modprobe@dm_mod.service - Load Kernel Module dm_mod. Sep 12 22:55:55.689047 systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. Sep 12 22:55:55.689072 systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. Sep 12 22:55:55.689089 systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. Sep 12 22:55:55.689111 systemd[1]: Finished systemd-network-generator.service - Generate network units from Kernel command line. Sep 12 22:55:55.689129 systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. Sep 12 22:55:55.689146 systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. Sep 12 22:55:55.689215 systemd-journald[1203]: Collecting audit messages is disabled. Sep 12 22:55:55.689258 systemd[1]: Reached target network-pre.target - Preparation for Network. Sep 12 22:55:55.689275 systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... Sep 12 22:55:55.689292 systemd-journald[1203]: Journal started Sep 12 22:55:55.689327 systemd-journald[1203]: Runtime Journal (/run/log/journal/3ad7b117211d4e308fb08802441a9118) is 6M, max 48.6M, 42.5M free. Sep 12 22:55:54.486114 systemd[1]: Queued start job for default target multi-user.target. Sep 12 22:55:54.516757 systemd[1]: Unnecessary job was removed for dev-vda6.device - /dev/vda6. Sep 12 22:55:54.520246 systemd[1]: systemd-journald.service: Deactivated successfully. Sep 12 22:55:55.702194 systemd[1]: remount-root.service - Remount Root File System was skipped because of an unmet condition check (ConditionPathIsReadWrite=!/). Sep 12 22:55:55.702513 systemd[1]: Reached target local-fs.target - Local File Systems. Sep 12 22:55:55.709857 kernel: fuse: init (API version 7.41) Sep 12 22:55:55.709988 systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. Sep 12 22:55:55.710020 kernel: ACPI: bus type drm_connector registered Sep 12 22:55:55.710038 kernel: loop: module loaded Sep 12 22:55:55.723391 systemd[1]: Starting ldconfig.service - Rebuild Dynamic Linker Cache... Sep 12 22:55:55.729356 systemd[1]: systemd-binfmt.service - Set Up Additional Binary Formats was skipped because no trigger condition checks were met. Sep 12 22:55:55.733575 systemd[1]: Starting systemd-hwdb-update.service - Rebuild Hardware Database... Sep 12 22:55:55.739020 systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). Sep 12 22:55:55.744260 systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... Sep 12 22:55:55.746363 systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... Sep 12 22:55:55.752424 systemd[1]: Starting systemd-sysext.service - Merge System Extension Images into /usr/ and /opt/... Sep 12 22:55:55.760723 systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... Sep 12 22:55:55.774455 systemd[1]: Started systemd-journald.service - Journal Service. Sep 12 22:55:55.781169 systemd[1]: modprobe@drm.service: Deactivated successfully. Sep 12 22:55:55.781558 systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. Sep 12 22:55:55.784512 systemd[1]: modprobe@fuse.service: Deactivated successfully. Sep 12 22:55:55.784809 systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. Sep 12 22:55:55.786742 systemd[1]: modprobe@loop.service: Deactivated successfully. Sep 12 22:55:55.787036 systemd[1]: Finished modprobe@loop.service - Load Kernel Module loop. Sep 12 22:55:55.790312 systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. Sep 12 22:55:55.793090 systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. Sep 12 22:55:55.799790 systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. Sep 12 22:55:55.816408 kernel: loop0: detected capacity change from 0 to 110984 Sep 12 22:55:55.833182 systemd-tmpfiles[1225]: ACLs are not supported, ignoring. Sep 12 22:55:55.833207 systemd-tmpfiles[1225]: ACLs are not supported, ignoring. Sep 12 22:55:55.836606 systemd[1]: Reached target first-boot-complete.target - First Boot Complete. Sep 12 22:55:55.851235 systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... Sep 12 22:55:55.857553 systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... Sep 12 22:55:55.862673 systemd[1]: Starting systemd-machine-id-commit.service - Save Transient machine-id to Disk... Sep 12 22:55:55.865700 systemd[1]: systemd-repart.service - Repartition Root Disk was skipped because no trigger condition checks were met. Sep 12 22:55:55.866476 systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. Sep 12 22:55:55.869628 systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. Sep 12 22:55:55.898692 systemd[1]: Starting systemd-sysusers.service - Create System Users... Sep 12 22:55:55.906279 systemd-journald[1203]: Time spent on flushing to /var/log/journal/3ad7b117211d4e308fb08802441a9118 is 45.655ms for 970 entries. Sep 12 22:55:55.906279 systemd-journald[1203]: System Journal (/var/log/journal/3ad7b117211d4e308fb08802441a9118) is 8M, max 195.6M, 187.6M free. Sep 12 22:55:56.068194 systemd-journald[1203]: Received client request to flush runtime journal. Sep 12 22:55:55.906680 systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. Sep 12 22:55:56.071804 systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. Sep 12 22:55:56.160856 systemd[1]: Finished systemd-machine-id-commit.service - Save Transient machine-id to Disk. Sep 12 22:55:56.187993 kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher Sep 12 22:55:56.191607 systemd[1]: Finished systemd-sysusers.service - Create System Users. Sep 12 22:55:56.201161 systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... Sep 12 22:55:56.248367 kernel: loop1: detected capacity change from 0 to 128016 Sep 12 22:55:56.254202 systemd-tmpfiles[1265]: ACLs are not supported, ignoring. Sep 12 22:55:56.255696 systemd-tmpfiles[1265]: ACLs are not supported, ignoring. Sep 12 22:55:56.267525 systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. Sep 12 22:55:56.343685 kernel: loop2: detected capacity change from 0 to 110984 Sep 12 22:55:56.377662 kernel: loop3: detected capacity change from 0 to 128016 Sep 12 22:55:56.426106 (sd-merge)[1269]: Using extensions 'containerd-flatcar', 'docker-flatcar'. Sep 12 22:55:56.426873 (sd-merge)[1269]: Merged extensions into '/usr'. Sep 12 22:55:56.521640 systemd[1]: Finished systemd-sysext.service - Merge System Extension Images into /usr/ and /opt/. Sep 12 22:55:56.538928 systemd[1]: etc-machine\x2did.mount: Deactivated successfully. Sep 12 22:55:56.549863 systemd[1]: Starting ensure-sysext.service... Sep 12 22:55:56.559522 systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... Sep 12 22:55:56.594319 systemd[1]: Reload requested from client PID 1271 ('systemctl') (unit ensure-sysext.service)... Sep 12 22:55:56.594359 systemd[1]: Reloading... Sep 12 22:55:56.703404 systemd-tmpfiles[1272]: /usr/lib/tmpfiles.d/nfs-utils.conf:6: Duplicate line for path "/var/lib/nfs/sm", ignoring. Sep 12 22:55:56.704120 systemd-tmpfiles[1272]: /usr/lib/tmpfiles.d/nfs-utils.conf:7: Duplicate line for path "/var/lib/nfs/sm.bak", ignoring. Sep 12 22:55:56.704908 systemd-tmpfiles[1272]: /usr/lib/tmpfiles.d/provision.conf:20: Duplicate line for path "/root", ignoring. Sep 12 22:55:56.705354 systemd-tmpfiles[1272]: /usr/lib/tmpfiles.d/systemd-flatcar.conf:6: Duplicate line for path "/var/log/journal", ignoring. Sep 12 22:55:56.708808 systemd-tmpfiles[1272]: /usr/lib/tmpfiles.d/systemd.conf:29: Duplicate line for path "/var/lib/systemd", ignoring. Sep 12 22:55:56.709432 systemd-tmpfiles[1272]: ACLs are not supported, ignoring. Sep 12 22:55:56.709626 systemd-tmpfiles[1272]: ACLs are not supported, ignoring. Sep 12 22:55:56.719992 systemd-tmpfiles[1272]: Detected autofs mount point /boot during canonicalization of boot. Sep 12 22:55:56.720191 systemd-tmpfiles[1272]: Skipping /boot Sep 12 22:55:56.797139 systemd-tmpfiles[1272]: Detected autofs mount point /boot during canonicalization of boot. Sep 12 22:55:56.797326 systemd-tmpfiles[1272]: Skipping /boot Sep 12 22:55:56.867370 zram_generator::config[1300]: No configuration found. Sep 12 22:55:57.337329 systemd[1]: Reloading finished in 742 ms. Sep 12 22:55:57.499317 systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. Sep 12 22:55:57.516635 systemd[1]: Starting audit-rules.service - Load Audit Rules... Sep 12 22:55:57.524981 systemd[1]: Starting clean-ca-certificates.service - Clean up broken links in /etc/ssl/certs... Sep 12 22:55:57.528537 systemd[1]: Starting systemd-journal-catalog-update.service - Rebuild Journal Catalog... Sep 12 22:55:57.555530 systemd[1]: Starting systemd-resolved.service - Network Name Resolution... Sep 12 22:55:57.568394 systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... Sep 12 22:55:57.577065 systemd[1]: proc-xen.mount - /proc/xen was skipped because of an unmet condition check (ConditionVirtualization=xen). Sep 12 22:55:57.577306 systemd[1]: ignition-delete-config.service - Ignition (delete config) was skipped because no trigger condition checks were met. Sep 12 22:55:57.579483 systemd[1]: Starting modprobe@dm_mod.service - Load Kernel Module dm_mod... Sep 12 22:55:57.589775 systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... Sep 12 22:55:57.616738 systemd[1]: Starting modprobe@loop.service - Load Kernel Module loop... Sep 12 22:55:57.689821 systemd[1]: systemd-binfmt.service - Set Up Additional Binary Formats was skipped because no trigger condition checks were met. Sep 12 22:55:57.690063 systemd[1]: systemd-hibernate-clear.service - Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67). Sep 12 22:55:57.690244 systemd[1]: xenserver-pv-version.service - Set fake PV driver version for XenServer was skipped because of an unmet condition check (ConditionVirtualization=xen). Sep 12 22:55:57.733904 systemd[1]: Starting systemd-userdbd.service - User Database Manager... Sep 12 22:55:57.743919 systemd[1]: Finished systemd-journal-catalog-update.service - Rebuild Journal Catalog. Sep 12 22:55:57.750270 systemd[1]: modprobe@dm_mod.service: Deactivated successfully. Sep 12 22:55:57.754258 systemd[1]: Finished modprobe@dm_mod.service - Load Kernel Module dm_mod. Sep 12 22:55:57.758716 systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. Sep 12 22:55:57.760502 systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. Sep 12 22:55:57.763961 systemd[1]: modprobe@loop.service: Deactivated successfully. Sep 12 22:55:57.764223 systemd[1]: Finished modprobe@loop.service - Load Kernel Module loop. Sep 12 22:55:57.813489 systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. Sep 12 22:55:57.843451 systemd[1]: Finished ensure-sysext.service. Sep 12 22:55:57.847277 systemd[1]: proc-xen.mount - /proc/xen was skipped because of an unmet condition check (ConditionVirtualization=xen). Sep 12 22:55:57.847630 systemd[1]: ignition-delete-config.service - Ignition (delete config) was skipped because no trigger condition checks were met. Sep 12 22:55:57.854068 systemd[1]: Starting modprobe@dm_mod.service - Load Kernel Module dm_mod... Sep 12 22:55:57.862572 systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... Sep 12 22:55:57.870275 systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... Sep 12 22:55:57.884773 systemd[1]: Starting modprobe@loop.service - Load Kernel Module loop... Sep 12 22:55:57.890615 systemd[1]: systemd-binfmt.service - Set Up Additional Binary Formats was skipped because no trigger condition checks were met. Sep 12 22:55:57.890674 systemd[1]: systemd-hibernate-clear.service - Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67). Sep 12 22:55:57.902837 systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... Sep 12 22:55:57.909362 systemd[1]: xenserver-pv-version.service - Set fake PV driver version for XenServer was skipped because of an unmet condition check (ConditionVirtualization=xen). Sep 12 22:55:57.913028 systemd[1]: modprobe@dm_mod.service: Deactivated successfully. Sep 12 22:55:57.921466 systemd[1]: Finished modprobe@dm_mod.service - Load Kernel Module dm_mod. Sep 12 22:55:57.924563 systemd[1]: modprobe@drm.service: Deactivated successfully. Sep 12 22:55:57.925414 systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. Sep 12 22:55:57.946116 systemd[1]: modprobe@loop.service: Deactivated successfully. Sep 12 22:55:57.946439 systemd[1]: Finished modprobe@loop.service - Load Kernel Module loop. Sep 12 22:55:57.948213 systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. Sep 12 22:55:57.948475 systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. Sep 12 22:55:57.955454 systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). Sep 12 22:55:57.962162 augenrules[1380]: No rules Sep 12 22:55:57.955555 systemd[1]: systemd-repart.service - Repartition Root Disk was skipped because no trigger condition checks were met. Sep 12 22:55:57.960878 systemd[1]: audit-rules.service: Deactivated successfully. Sep 12 22:55:57.961363 systemd[1]: Finished audit-rules.service - Load Audit Rules. Sep 12 22:55:57.968707 systemd[1]: Finished clean-ca-certificates.service - Clean up broken links in /etc/ssl/certs. Sep 12 22:55:57.977565 systemd[1]: update-ca-certificates.service - Update CA bundle at /etc/ssl/certs/ca-certificates.crt was skipped because of an unmet condition check (ConditionPathIsSymbolicLink=!/etc/ssl/certs/ca-certificates.crt). Sep 12 22:55:58.003595 ldconfig[1220]: /sbin/ldconfig: /usr/lib/ld.so.conf is not an ELF file - it has the wrong magic bytes at the start. Sep 12 22:55:58.101627 systemd[1]: Started systemd-userdbd.service - User Database Manager. Sep 12 22:55:58.125030 systemd[1]: Finished ldconfig.service - Rebuild Dynamic Linker Cache. Sep 12 22:55:58.188041 systemd[1]: Finished systemd-hwdb-update.service - Rebuild Hardware Database. Sep 12 22:55:58.216107 systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... Sep 12 22:55:58.227297 systemd[1]: Starting systemd-update-done.service - Update is Completed... Sep 12 22:55:58.270764 systemd[1]: Finished systemd-update-done.service - Update is Completed. Sep 12 22:55:58.338464 systemd-udevd[1395]: Using default interface naming scheme 'v255'. Sep 12 22:55:58.346653 systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. Sep 12 22:55:58.349487 systemd[1]: Reached target time-set.target - System Time Set. Sep 12 22:55:58.378225 systemd-resolved[1340]: Positive Trust Anchors: Sep 12 22:55:58.378753 systemd-resolved[1340]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d Sep 12 22:55:58.378817 systemd-resolved[1340]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test Sep 12 22:55:58.386784 systemd-resolved[1340]: Defaulting to hostname 'linux'. Sep 12 22:55:58.393604 systemd[1]: Started systemd-resolved.service - Network Name Resolution. Sep 12 22:55:58.400539 systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. Sep 12 22:55:58.416993 systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. Sep 12 22:55:58.423696 systemd[1]: Reached target sysinit.target - System Initialization. Sep 12 22:55:58.426226 systemd[1]: Started motdgen.path - Watch for update engine configuration changes. Sep 12 22:55:58.428007 systemd[1]: Started user-cloudinit@var-lib-flatcar\x2dinstall-user_data.path - Watch for a cloud-config at /var/lib/flatcar-install/user_data. Sep 12 22:55:58.431624 systemd[1]: Started google-oslogin-cache.timer - NSS cache refresh timer. Sep 12 22:55:58.433567 systemd[1]: Started logrotate.timer - Daily rotation of log files. Sep 12 22:55:58.435065 systemd[1]: Started mdadm.timer - Weekly check for MD array's redundancy information.. Sep 12 22:55:58.436511 systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. Sep 12 22:55:58.437906 systemd[1]: update-engine-stub.timer - Update Engine Stub Timer was skipped because of an unmet condition check (ConditionPathExists=/usr/.noupdate). Sep 12 22:55:58.437953 systemd[1]: Reached target paths.target - Path Units. Sep 12 22:55:58.440252 systemd[1]: Reached target timers.target - Timer Units. Sep 12 22:55:58.467441 systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. Sep 12 22:55:58.474902 systemd[1]: Starting docker.socket - Docker Socket for the API... Sep 12 22:55:58.479708 systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). Sep 12 22:55:58.482441 systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). Sep 12 22:55:58.484430 systemd[1]: Reached target ssh-access.target - SSH Access Available. Sep 12 22:55:58.553441 systemd[1]: Listening on sshd.socket - OpenSSH Server Socket. Sep 12 22:55:58.561991 systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. Sep 12 22:55:58.567734 systemd[1]: Starting systemd-networkd.service - Network Configuration... Sep 12 22:55:58.570841 systemd[1]: Listening on docker.socket - Docker Socket for the API. Sep 12 22:55:58.582884 systemd[1]: Condition check resulted in dev-ttyS0.device - /dev/ttyS0 being skipped. Sep 12 22:55:58.585671 systemd[1]: Reached target sockets.target - Socket Units. Sep 12 22:55:58.608027 systemd[1]: Reached target basic.target - Basic System. Sep 12 22:55:58.697153 systemd[1]: addon-config@oem.service - Configure Addon /oem was skipped because no trigger condition checks were met. Sep 12 22:55:58.697199 systemd[1]: addon-run@oem.service - Run Addon /oem was skipped because no trigger condition checks were met. Sep 12 22:55:58.704968 systemd[1]: Starting dbus.service - D-Bus System Message Bus... Sep 12 22:55:58.711522 systemd[1]: Starting dracut-shutdown.service - Restore /run/initramfs on shutdown... Sep 12 22:55:58.718812 systemd[1]: Starting enable-oem-cloudinit.service - Enable cloudinit... Sep 12 22:55:58.724511 systemd[1]: Starting extend-filesystems.service - Extend Filesystems... Sep 12 22:55:58.725686 systemd[1]: flatcar-setup-environment.service - Modifies /etc/environment for CoreOS was skipped because of an unmet condition check (ConditionPathExists=/oem/bin/flatcar-setup-environment). Sep 12 22:55:58.910398 kernel: mousedev: PS/2 mouse device common for all mice Sep 12 22:55:58.859545 systemd[1]: Starting google-oslogin-cache.service - NSS cache refresh... Sep 12 22:55:58.919248 systemd[1]: Starting motdgen.service - Generate /run/flatcar/motd... Sep 12 22:55:58.922376 jq[1436]: false Sep 12 22:55:58.958367 kernel: input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3 Sep 12 22:55:58.965188 systemd[1]: Starting ssh-key-proc-cmdline.service - Install an ssh key from /proc/cmdline... Sep 12 22:55:58.970637 extend-filesystems[1437]: Found /dev/vda6 Sep 12 22:55:58.976387 google_oslogin_nss_cache[1438]: oslogin_cache_refresh[1438]: Refreshing passwd entry cache Sep 12 22:55:58.974465 oslogin_cache_refresh[1438]: Refreshing passwd entry cache Sep 12 22:55:58.982296 oslogin_cache_refresh[1438]: Failure getting users, quitting Sep 12 22:55:58.982605 google_oslogin_nss_cache[1438]: oslogin_cache_refresh[1438]: Failure getting users, quitting Sep 12 22:55:58.982605 google_oslogin_nss_cache[1438]: oslogin_cache_refresh[1438]: Produced empty passwd cache file, removing /etc/oslogin_passwd.cache.bak. Sep 12 22:55:58.982605 google_oslogin_nss_cache[1438]: oslogin_cache_refresh[1438]: Refreshing group entry cache Sep 12 22:55:58.982316 oslogin_cache_refresh[1438]: Produced empty passwd cache file, removing /etc/oslogin_passwd.cache.bak. Sep 12 22:55:58.982407 oslogin_cache_refresh[1438]: Refreshing group entry cache Sep 12 22:55:58.983367 google_oslogin_nss_cache[1438]: oslogin_cache_refresh[1438]: Failure getting groups, quitting Sep 12 22:55:58.983367 google_oslogin_nss_cache[1438]: oslogin_cache_refresh[1438]: Produced empty group cache file, removing /etc/oslogin_group.cache.bak. Sep 12 22:55:58.982971 oslogin_cache_refresh[1438]: Failure getting groups, quitting Sep 12 22:55:58.982981 oslogin_cache_refresh[1438]: Produced empty group cache file, removing /etc/oslogin_group.cache.bak. Sep 12 22:55:58.984174 extend-filesystems[1437]: Found /dev/vda9 Sep 12 22:55:58.988065 systemd[1]: Starting sshd-keygen.service - Generate sshd host keys... Sep 12 22:55:58.989782 extend-filesystems[1437]: Checking size of /dev/vda9 Sep 12 22:55:58.995210 kernel: ACPI: button: Power Button [PWRF] Sep 12 22:55:59.003178 systemd[1]: Starting systemd-logind.service - User Login Management... Sep 12 22:55:59.007896 systemd[1]: tcsd.service - TCG Core Services Daemon was skipped because of an unmet condition check (ConditionPathExists=/dev/tpm0). Sep 12 22:55:59.008790 systemd[1]: cgroup compatibility translation between legacy and unified hierarchy settings activated. See cgroup-compat debug messages for details. Sep 12 22:55:59.015206 kernel: i801_smbus 0000:00:1f.3: SMBus using PCI interrupt Sep 12 22:55:59.015573 kernel: i2c i2c-0: Memory type 0x07 not supported yet, not instantiating SPD Sep 12 22:55:59.012681 systemd[1]: Starting update-engine.service - Update Engine... Sep 12 22:55:59.014519 systemd[1]: Starting update-ssh-keys-after-ignition.service - Run update-ssh-keys once after Ignition... Sep 12 22:55:59.021417 systemd[1]: Finished dracut-shutdown.service - Restore /run/initramfs on shutdown. Sep 12 22:55:59.021901 systemd[1]: enable-oem-cloudinit.service: Skipped due to 'exec-condition'. Sep 12 22:55:59.022204 systemd[1]: Condition check resulted in enable-oem-cloudinit.service - Enable cloudinit being skipped. Sep 12 22:55:59.022682 systemd[1]: google-oslogin-cache.service: Deactivated successfully. Sep 12 22:55:59.023126 systemd[1]: Finished google-oslogin-cache.service - NSS cache refresh. Sep 12 22:55:59.028601 systemd[1]: ssh-key-proc-cmdline.service: Deactivated successfully. Sep 12 22:55:59.029067 systemd[1]: Finished ssh-key-proc-cmdline.service - Install an ssh key from /proc/cmdline. Sep 12 22:55:59.065470 jq[1454]: true Sep 12 22:55:59.079963 extend-filesystems[1437]: Old size kept for /dev/vda9 Sep 12 22:55:59.079804 systemd[1]: extend-filesystems.service: Deactivated successfully. Sep 12 22:55:59.083466 systemd[1]: Finished extend-filesystems.service - Extend Filesystems. Sep 12 22:55:59.093409 systemd[1]: Found device dev-disk-by\x2dlabel-OEM.device - /dev/disk/by-label/OEM. Sep 12 22:55:59.102130 update_engine[1453]: I20250912 22:55:59.101994 1453 main.cc:92] Flatcar Update Engine starting Sep 12 22:55:59.104202 jq[1468]: true Sep 12 22:55:59.127312 systemd[1]: motdgen.service: Deactivated successfully. Sep 12 22:55:59.127688 systemd[1]: Finished motdgen.service - Generate /run/flatcar/motd. Sep 12 22:55:59.171539 systemd[1]: Starting systemd-fsck@dev-disk-by\x2dlabel-OEM.service - File System Check on /dev/disk/by-label/OEM... Sep 12 22:55:59.192886 dbus-daemon[1432]: [system] SELinux support is enabled Sep 12 22:55:59.193132 systemd[1]: Started dbus.service - D-Bus System Message Bus. Sep 12 22:55:59.200024 update_engine[1453]: I20250912 22:55:59.199963 1453 update_check_scheduler.cc:74] Next update check in 9m13s Sep 12 22:55:59.206555 systemd[1]: system-cloudinit@usr-share-oem-cloud\x2dconfig.yml.service - Load cloud-config from /usr/share/oem/cloud-config.yml was skipped because of an unmet condition check (ConditionFileNotEmpty=/usr/share/oem/cloud-config.yml). Sep 12 22:55:59.206596 systemd[1]: Reached target system-config.target - Load system-provided cloud configs. Sep 12 22:55:59.208190 systemd[1]: user-cloudinit-proc-cmdline.service - Load cloud-config from url defined in /proc/cmdline was skipped because of an unmet condition check (ConditionKernelCommandLine=cloud-config-url). Sep 12 22:55:59.208215 systemd[1]: Reached target user-config.target - Load user-provided cloud configs. Sep 12 22:55:59.212023 systemd[1]: Started update-engine.service - Update Engine. Sep 12 22:55:59.219400 systemd[1]: Started locksmithd.service - Cluster reboot manager. Sep 12 22:55:59.221538 systemd-networkd[1430]: lo: Link UP Sep 12 22:55:59.221546 systemd-networkd[1430]: lo: Gained carrier Sep 12 22:55:59.228895 systemd-networkd[1430]: Enumeration completed Sep 12 22:55:59.229820 systemd-networkd[1430]: eth0: found matching network '/usr/lib/systemd/network/zz-default.network', based on potentially unpredictable interface name. Sep 12 22:55:59.229827 systemd-networkd[1430]: eth0: Configuring with /usr/lib/systemd/network/zz-default.network. Sep 12 22:55:59.230817 systemd-networkd[1430]: eth0: Link UP Sep 12 22:55:59.231024 systemd-networkd[1430]: eth0: Gained carrier Sep 12 22:55:59.231043 systemd-networkd[1430]: eth0: found matching network '/usr/lib/systemd/network/zz-default.network', based on potentially unpredictable interface name. Sep 12 22:55:59.232036 systemd[1]: Started systemd-networkd.service - Network Configuration. Sep 12 22:55:59.232615 systemd[1]: Reached target network.target - Network. Sep 12 22:55:59.235729 systemd-logind[1452]: New seat seat0. Sep 12 22:55:59.247818 systemd[1]: Starting containerd.service - containerd container runtime... Sep 12 22:55:59.256917 systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... Sep 12 22:55:59.258691 systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... Sep 12 22:55:59.258879 systemd[1]: Started systemd-logind.service - User Login Management. Sep 12 22:55:59.284471 systemd[1]: Starting systemd-vconsole-setup.service - Virtual Console Setup... Sep 12 22:55:59.290423 systemd-networkd[1430]: eth0: DHCPv4 address 10.0.0.63/16, gateway 10.0.0.1 acquired from 10.0.0.1 Sep 12 22:55:59.291532 systemd-timesyncd[1374]: Network configuration changed, trying to establish connection. Sep 12 22:55:59.293859 systemd[1]: Finished systemd-fsck@dev-disk-by\x2dlabel-OEM.service - File System Check on /dev/disk/by-label/OEM. Sep 12 22:56:00.220531 systemd-timesyncd[1374]: Contacted time server 10.0.0.1:123 (10.0.0.1). Sep 12 22:56:00.220834 systemd-timesyncd[1374]: Initial clock synchronization to Fri 2025-09-12 22:56:00.219558 UTC. Sep 12 22:56:00.221229 systemd-resolved[1340]: Clock change detected. Flushing caches. Sep 12 22:56:00.274076 (ntainerd)[1510]: containerd.service: Referenced but unset environment variable evaluates to an empty string: TORCX_IMAGEDIR, TORCX_UNPACKDIR Sep 12 22:56:00.412464 systemd[1]: Created slice system-sshd.slice - Slice /system/sshd. Sep 12 22:56:00.427355 bash[1504]: Updated "/home/core/.ssh/authorized_keys" Sep 12 22:56:00.418246 systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. Sep 12 22:56:00.444555 systemd[1]: Finished update-ssh-keys-after-ignition.service - Run update-ssh-keys once after Ignition. Sep 12 22:56:00.464476 systemd[1]: sshkeys.service was skipped because no trigger condition checks were met. Sep 12 22:56:00.519346 sshd_keygen[1479]: ssh-keygen: generating new host keys: RSA ECDSA ED25519 Sep 12 22:56:00.670586 systemd-logind[1452]: Watching system buttons on /dev/input/event0 (AT Translated Set 2 keyboard) Sep 12 22:56:00.724046 systemd[1]: Finished sshd-keygen.service - Generate sshd host keys. Sep 12 22:56:00.727123 systemd[1]: Starting issuegen.service - Generate /run/issue... Sep 12 22:56:00.730507 systemd[1]: Started sshd@0-10.0.0.63:22-10.0.0.1:39848.service - OpenSSH per-connection server daemon (10.0.0.1:39848). Sep 12 22:56:00.753718 systemd-logind[1452]: Watching system buttons on /dev/input/event2 (Power Button) Sep 12 22:56:00.848250 locksmithd[1490]: locksmithd starting currentOperation="UPDATE_STATUS_IDLE" strategy="reboot" Sep 12 22:56:00.855494 systemd[1]: issuegen.service: Deactivated successfully. Sep 12 22:56:00.855867 systemd[1]: Finished issuegen.service - Generate /run/issue. Sep 12 22:56:00.860600 systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... Sep 12 22:56:01.075077 systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. Sep 12 22:56:01.210741 sshd[1527]: Accepted publickey for core from 10.0.0.1 port 39848 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:01.213677 sshd-session[1527]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:01.216565 systemd[1]: Started getty@tty1.service - Getty on tty1. Sep 12 22:56:01.241763 systemd[1]: Started serial-getty@ttyS0.service - Serial Getty on ttyS0. Sep 12 22:56:01.242203 systemd[1]: Reached target getty.target - Login Prompts. Sep 12 22:56:01.255012 systemd-networkd[1430]: eth0: Gained IPv6LL Sep 12 22:56:01.277676 systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. Sep 12 22:56:01.304825 systemd-logind[1452]: New session 1 of user core. Sep 12 22:56:01.306223 systemd[1]: Finished systemd-vconsole-setup.service - Virtual Console Setup. Sep 12 22:56:01.316748 systemd[1]: Created slice user-500.slice - User Slice of UID 500. Sep 12 22:56:01.319138 systemd[1]: Reached target network-online.target - Network is Online. Sep 12 22:56:01.326130 systemd[1]: Starting coreos-metadata.service - QEMU metadata agent... Sep 12 22:56:01.334673 systemd[1]: Starting nvidia.service - NVIDIA Configure Service... Sep 12 22:56:01.349045 systemd[1]: Starting user-runtime-dir@500.service - User Runtime Directory /run/user/500... Sep 12 22:56:01.417276 kernel: kvm_amd: TSC scaling supported Sep 12 22:56:01.417340 kernel: kvm_amd: Nested Virtualization enabled Sep 12 22:56:01.417359 kernel: kvm_amd: Nested Paging enabled Sep 12 22:56:01.418465 kernel: kvm_amd: LBR virtualization supported Sep 12 22:56:01.418496 kernel: kvm_amd: Virtual VMLOAD VMSAVE supported Sep 12 22:56:01.422389 kernel: kvm_amd: Virtual GIF supported Sep 12 22:56:01.466199 containerd[1510]: time="2025-09-12T22:56:01Z" level=warning msg="Ignoring unknown key in TOML" column=1 error="strict mode: fields in the document are missing in the target struct" file=/usr/share/containerd/config.toml key=subreaper row=8 Sep 12 22:56:01.467147 containerd[1510]: time="2025-09-12T22:56:01.467098321Z" level=info msg="starting containerd" revision=fb4c30d4ede3531652d86197bf3fc9515e5276d9 version=v2.0.5 Sep 12 22:56:01.476399 systemd[1]: Finished user-runtime-dir@500.service - User Runtime Directory /run/user/500. Sep 12 22:56:01.481839 systemd[1]: Finished nvidia.service - NVIDIA Configure Service. Sep 12 22:56:01.484003 systemd[1]: coreos-metadata.service: Deactivated successfully. Sep 12 22:56:01.484472 systemd[1]: Finished coreos-metadata.service - QEMU metadata agent. Sep 12 22:56:01.505450 systemd[1]: Starting etcd-member.service - etcd (System Application Container)... Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.506642795Z" level=warning msg="Configuration migrated from version 2, use `containerd config migrate` to avoid migration" t="12.473µs" Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.506697839Z" level=info msg="loading plugin" id=io.containerd.image-verifier.v1.bindir type=io.containerd.image-verifier.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.506722314Z" level=info msg="loading plugin" id=io.containerd.internal.v1.opt type=io.containerd.internal.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.508793640Z" level=info msg="loading plugin" id=io.containerd.warning.v1.deprecations type=io.containerd.warning.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.508827994Z" level=info msg="loading plugin" id=io.containerd.content.v1.content type=io.containerd.content.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.508985149Z" level=info msg="loading plugin" id=io.containerd.snapshotter.v1.blockfile type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.509081580Z" level=info msg="skip loading plugin" error="no scratch file generator: skip plugin" id=io.containerd.snapshotter.v1.blockfile type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.509099153Z" level=info msg="loading plugin" id=io.containerd.snapshotter.v1.btrfs type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.509517127Z" level=info msg="skip loading plugin" error="path /var/lib/containerd/io.containerd.snapshotter.v1.btrfs (ext4) must be a btrfs filesystem to be used with the btrfs snapshotter: skip plugin" id=io.containerd.snapshotter.v1.btrfs type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.509536744Z" level=info msg="loading plugin" id=io.containerd.snapshotter.v1.devmapper type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.509552543Z" level=info msg="skip loading plugin" error="devmapper not configured: skip plugin" id=io.containerd.snapshotter.v1.devmapper type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511362 containerd[1510]: time="2025-09-12T22:56:01.509564025Z" level=info msg="loading plugin" id=io.containerd.snapshotter.v1.native type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511849 containerd[1510]: time="2025-09-12T22:56:01.509723083Z" level=info msg="loading plugin" id=io.containerd.snapshotter.v1.overlayfs type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511849 containerd[1510]: time="2025-09-12T22:56:01.510023086Z" level=info msg="loading plugin" id=io.containerd.snapshotter.v1.zfs type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511849 containerd[1510]: time="2025-09-12T22:56:01.510066888Z" level=info msg="skip loading plugin" error="lstat /var/lib/containerd/io.containerd.snapshotter.v1.zfs: no such file or directory: skip plugin" id=io.containerd.snapshotter.v1.zfs type=io.containerd.snapshotter.v1 Sep 12 22:56:01.511849 containerd[1510]: time="2025-09-12T22:56:01.510080463Z" level=info msg="loading plugin" id=io.containerd.event.v1.exchange type=io.containerd.event.v1 Sep 12 22:56:01.511849 containerd[1510]: time="2025-09-12T22:56:01.510147699Z" level=info msg="loading plugin" id=io.containerd.monitor.task.v1.cgroups type=io.containerd.monitor.task.v1 Sep 12 22:56:01.511849 containerd[1510]: time="2025-09-12T22:56:01.510611319Z" level=info msg="loading plugin" id=io.containerd.metadata.v1.bolt type=io.containerd.metadata.v1 Sep 12 22:56:01.511413 systemd[1]: packet-phone-home.service - Report Success to Packet was skipped because no trigger condition checks were met. Sep 12 22:56:01.512842 containerd[1510]: time="2025-09-12T22:56:01.512797039Z" level=info msg="metadata content store policy set" policy=shared Sep 12 22:56:01.514427 systemd[1]: Starting user@500.service - User Manager for UID 500... Sep 12 22:56:01.533707 containerd[1510]: time="2025-09-12T22:56:01.532550651Z" level=info msg="loading plugin" id=io.containerd.gc.v1.scheduler type=io.containerd.gc.v1 Sep 12 22:56:01.534082 containerd[1510]: time="2025-09-12T22:56:01.534015839Z" level=info msg="loading plugin" id=io.containerd.differ.v1.walking type=io.containerd.differ.v1 Sep 12 22:56:01.534082 containerd[1510]: time="2025-09-12T22:56:01.534048471Z" level=info msg="loading plugin" id=io.containerd.lease.v1.manager type=io.containerd.lease.v1 Sep 12 22:56:01.534280 containerd[1510]: time="2025-09-12T22:56:01.534166953Z" level=info msg="loading plugin" id=io.containerd.service.v1.containers-service type=io.containerd.service.v1 Sep 12 22:56:01.534280 containerd[1510]: time="2025-09-12T22:56:01.534222307Z" level=info msg="loading plugin" id=io.containerd.service.v1.content-service type=io.containerd.service.v1 Sep 12 22:56:01.534280 containerd[1510]: time="2025-09-12T22:56:01.534238146Z" level=info msg="loading plugin" id=io.containerd.service.v1.diff-service type=io.containerd.service.v1 Sep 12 22:56:01.534280 containerd[1510]: time="2025-09-12T22:56:01.534256711Z" level=info msg="loading plugin" id=io.containerd.service.v1.images-service type=io.containerd.service.v1 Sep 12 22:56:01.534521 containerd[1510]: time="2025-09-12T22:56:01.534460123Z" level=info msg="loading plugin" id=io.containerd.service.v1.introspection-service type=io.containerd.service.v1 Sep 12 22:56:01.534521 containerd[1510]: time="2025-09-12T22:56:01.534486091Z" level=info msg="loading plugin" id=io.containerd.service.v1.namespaces-service type=io.containerd.service.v1 Sep 12 22:56:01.534694 containerd[1510]: time="2025-09-12T22:56:01.534502272Z" level=info msg="loading plugin" id=io.containerd.service.v1.snapshots-service type=io.containerd.service.v1 Sep 12 22:56:01.534694 containerd[1510]: time="2025-09-12T22:56:01.534627887Z" level=info msg="loading plugin" id=io.containerd.shim.v1.manager type=io.containerd.shim.v1 Sep 12 22:56:01.534694 containerd[1510]: time="2025-09-12T22:56:01.534655800Z" level=info msg="loading plugin" id=io.containerd.runtime.v2.task type=io.containerd.runtime.v2 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535161378Z" level=info msg="loading plugin" id=io.containerd.service.v1.tasks-service type=io.containerd.service.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535218926Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.containers type=io.containerd.grpc.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535242670Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.content type=io.containerd.grpc.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535271865Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.diff type=io.containerd.grpc.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535288286Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.events type=io.containerd.grpc.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535302723Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.images type=io.containerd.grpc.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535318553Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.introspection type=io.containerd.grpc.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535335705Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.leases type=io.containerd.grpc.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535350974Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.namespaces type=io.containerd.grpc.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535365852Z" level=info msg="loading plugin" id=io.containerd.sandbox.store.v1.local type=io.containerd.sandbox.store.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535381791Z" level=info msg="loading plugin" id=io.containerd.cri.v1.images type=io.containerd.cri.v1 Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535467192Z" level=info msg="Get image filesystem path \"/var/lib/containerd/io.containerd.snapshotter.v1.overlayfs\" for snapshotter \"overlayfs\"" Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535484594Z" level=info msg="Start snapshots syncer" Sep 12 22:56:01.536463 containerd[1510]: time="2025-09-12T22:56:01.535517636Z" level=info msg="loading plugin" id=io.containerd.cri.v1.runtime type=io.containerd.cri.v1 Sep 12 22:56:01.539055 containerd[1510]: time="2025-09-12T22:56:01.538968108Z" level=info msg="starting cri plugin" config="{\"containerd\":{\"defaultRuntimeName\":\"runc\",\"runtimes\":{\"runc\":{\"runtimeType\":\"io.containerd.runc.v2\",\"runtimePath\":\"\",\"PodAnnotations\":null,\"ContainerAnnotations\":null,\"options\":{\"BinaryName\":\"\",\"CriuImagePath\":\"\",\"CriuWorkPath\":\"\",\"IoGid\":0,\"IoUid\":0,\"NoNewKeyring\":false,\"Root\":\"\",\"ShimCgroup\":\"\",\"SystemdCgroup\":true},\"privileged_without_host_devices\":false,\"privileged_without_host_devices_all_devices_allowed\":false,\"baseRuntimeSpec\":\"\",\"cniConfDir\":\"\",\"cniMaxConfNum\":0,\"snapshotter\":\"\",\"sandboxer\":\"podsandbox\",\"io_type\":\"\"}},\"ignoreBlockIONotEnabledErrors\":false,\"ignoreRdtNotEnabledErrors\":false},\"cni\":{\"binDir\":\"/opt/cni/bin\",\"confDir\":\"/etc/cni/net.d\",\"maxConfNum\":1,\"setupSerially\":false,\"confTemplate\":\"\",\"ipPref\":\"\",\"useInternalLoopback\":false},\"enableSelinux\":true,\"selinuxCategoryRange\":1024,\"maxContainerLogSize\":16384,\"disableApparmor\":false,\"restrictOOMScoreAdj\":false,\"disableProcMount\":false,\"unsetSeccompProfile\":\"\",\"tolerateMissingHugetlbController\":true,\"disableHugetlbController\":true,\"device_ownership_from_security_context\":false,\"ignoreImageDefinedVolumes\":false,\"netnsMountsUnderStateDir\":false,\"enableUnprivilegedPorts\":true,\"enableUnprivilegedICMP\":true,\"enableCDI\":true,\"cdiSpecDirs\":[\"/etc/cdi\",\"/var/run/cdi\"],\"drainExecSyncIOTimeout\":\"0s\",\"ignoreDeprecationWarnings\":null,\"containerdRootDir\":\"/var/lib/containerd\",\"containerdEndpoint\":\"/run/containerd/containerd.sock\",\"rootDir\":\"/var/lib/containerd/io.containerd.grpc.v1.cri\",\"stateDir\":\"/run/containerd/io.containerd.grpc.v1.cri\"}" Sep 12 22:56:01.539339 containerd[1510]: time="2025-09-12T22:56:01.539059660Z" level=info msg="loading plugin" id=io.containerd.podsandbox.controller.v1.podsandbox type=io.containerd.podsandbox.controller.v1 Sep 12 22:56:01.539339 containerd[1510]: time="2025-09-12T22:56:01.539276276Z" level=info msg="loading plugin" id=io.containerd.sandbox.controller.v1.shim type=io.containerd.sandbox.controller.v1 Sep 12 22:56:01.539585 containerd[1510]: time="2025-09-12T22:56:01.539538248Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.sandbox-controllers type=io.containerd.grpc.v1 Sep 12 22:56:01.539585 containerd[1510]: time="2025-09-12T22:56:01.539581759Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.sandboxes type=io.containerd.grpc.v1 Sep 12 22:56:01.539657 containerd[1510]: time="2025-09-12T22:56:01.539599182Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.snapshots type=io.containerd.grpc.v1 Sep 12 22:56:01.539657 containerd[1510]: time="2025-09-12T22:56:01.539615433Z" level=info msg="loading plugin" id=io.containerd.streaming.v1.manager type=io.containerd.streaming.v1 Sep 12 22:56:01.539657 containerd[1510]: time="2025-09-12T22:56:01.539631964Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.streaming type=io.containerd.grpc.v1 Sep 12 22:56:01.539657 containerd[1510]: time="2025-09-12T22:56:01.539648515Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.tasks type=io.containerd.grpc.v1 Sep 12 22:56:01.540015 containerd[1510]: time="2025-09-12T22:56:01.539665657Z" level=info msg="loading plugin" id=io.containerd.transfer.v1.local type=io.containerd.transfer.v1 Sep 12 22:56:01.541797 containerd[1510]: time="2025-09-12T22:56:01.541743915Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.transfer type=io.containerd.grpc.v1 Sep 12 22:56:01.541797 containerd[1510]: time="2025-09-12T22:56:01.541779973Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.version type=io.containerd.grpc.v1 Sep 12 22:56:01.541797 containerd[1510]: time="2025-09-12T22:56:01.541798708Z" level=info msg="loading plugin" id=io.containerd.monitor.container.v1.restart type=io.containerd.monitor.container.v1 Sep 12 22:56:01.541909 containerd[1510]: time="2025-09-12T22:56:01.541852078Z" level=info msg="loading plugin" id=io.containerd.tracing.processor.v1.otlp type=io.containerd.tracing.processor.v1 Sep 12 22:56:01.541909 containerd[1510]: time="2025-09-12T22:56:01.541873558Z" level=info msg="skip loading plugin" error="skip plugin: tracing endpoint not configured" id=io.containerd.tracing.processor.v1.otlp type=io.containerd.tracing.processor.v1 Sep 12 22:56:01.541964 containerd[1510]: time="2025-09-12T22:56:01.541886062Z" level=info msg="loading plugin" id=io.containerd.internal.v1.tracing type=io.containerd.internal.v1 Sep 12 22:56:01.541993 containerd[1510]: time="2025-09-12T22:56:01.541971772Z" level=info msg="skip loading plugin" error="skip plugin: tracing endpoint not configured" id=io.containerd.internal.v1.tracing type=io.containerd.internal.v1 Sep 12 22:56:01.541993 containerd[1510]: time="2025-09-12T22:56:01.541989125Z" level=info msg="loading plugin" id=io.containerd.ttrpc.v1.otelttrpc type=io.containerd.ttrpc.v1 Sep 12 22:56:01.542048 containerd[1510]: time="2025-09-12T22:56:01.542021987Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.healthcheck type=io.containerd.grpc.v1 Sep 12 22:56:01.542048 containerd[1510]: time="2025-09-12T22:56:01.542042806Z" level=info msg="loading plugin" id=io.containerd.nri.v1.nri type=io.containerd.nri.v1 Sep 12 22:56:01.542111 containerd[1510]: time="2025-09-12T22:56:01.542067722Z" level=info msg="runtime interface created" Sep 12 22:56:01.542111 containerd[1510]: time="2025-09-12T22:56:01.542075397Z" level=info msg="created NRI interface" Sep 12 22:56:01.542111 containerd[1510]: time="2025-09-12T22:56:01.542086327Z" level=info msg="loading plugin" id=io.containerd.grpc.v1.cri type=io.containerd.grpc.v1 Sep 12 22:56:01.542111 containerd[1510]: time="2025-09-12T22:56:01.542105052Z" level=info msg="Connect containerd service" Sep 12 22:56:01.542232 containerd[1510]: time="2025-09-12T22:56:01.542139407Z" level=info msg="using experimental NRI integration - disable nri plugin to prevent this" Sep 12 22:56:01.544705 containerd[1510]: time="2025-09-12T22:56:01.544489555Z" level=error msg="failed to load cni during init, please check CRI plugin status before setting up network for pods" error="cni config load failed: no network config found in /etc/cni/net.d: cni plugin not initialized: failed to load cni config" Sep 12 22:56:01.564013 (systemd)[1570]: pam_unix(systemd-user:session): session opened for user core(uid=500) by (uid=0) Sep 12 22:56:01.578869 systemd-logind[1452]: New session c1 of user core. Sep 12 22:56:01.643727 (-wrapper)[1569]: etcd-member.service: Referenced but unset environment variable evaluates to an empty string: ETCD_OPTS Sep 12 22:56:02.191100 systemd[1570]: Queued start job for default target default.target. Sep 12 22:56:02.348063 kernel: EDAC MC: Ver: 3.0.0 Sep 12 22:56:02.353637 systemd[1570]: Created slice app.slice - User Application Slice. Sep 12 22:56:02.353686 systemd[1570]: Reached target paths.target - Paths. Sep 12 22:56:02.353745 systemd[1570]: Reached target timers.target - Timers. Sep 12 22:56:02.393579 systemd[1570]: Starting dbus.socket - D-Bus User Message Bus Socket... Sep 12 22:56:02.537015 systemd[1570]: Listening on dbus.socket - D-Bus User Message Bus Socket. Sep 12 22:56:02.537206 systemd[1570]: Reached target sockets.target - Sockets. Sep 12 22:56:02.537271 systemd[1570]: Reached target basic.target - Basic System. Sep 12 22:56:02.537324 systemd[1570]: Reached target default.target - Main User Target. Sep 12 22:56:02.537366 systemd[1570]: Startup finished in 897ms. Sep 12 22:56:02.537610 systemd[1]: Started user@500.service - User Manager for UID 500. Sep 12 22:56:02.579093 systemd[1]: Started session-1.scope - Session 1 of User core. Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589343723Z" level=info msg="Start subscribing containerd event" Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589414696Z" level=info msg="Start recovering state" Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589561371Z" level=info msg="Start event monitor" Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589589504Z" level=info msg="Start cni network conf syncer for default" Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589902381Z" level=info msg="Start streaming server" Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589932036Z" level=info msg="Registered namespace \"k8s.io\" with NRI" Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589946674Z" level=info msg="runtime interface starting up..." Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589958586Z" level=info msg="starting plugins..." Sep 12 22:56:02.590202 containerd[1510]: time="2025-09-12T22:56:02.589986679Z" level=info msg="Synchronizing NRI (plugin) with current runtime state" Sep 12 22:56:02.591092 containerd[1510]: time="2025-09-12T22:56:02.591069810Z" level=info msg=serving... address=/run/containerd/containerd.sock.ttrpc Sep 12 22:56:02.591348 containerd[1510]: time="2025-09-12T22:56:02.591330249Z" level=info msg=serving... address=/run/containerd/containerd.sock Sep 12 22:56:02.591489 containerd[1510]: time="2025-09-12T22:56:02.591473147Z" level=info msg="containerd successfully booted in 1.126338s" Sep 12 22:56:02.591552 systemd[1]: Started containerd.service - containerd container runtime. Sep 12 22:56:02.888154 systemd[1]: Started sshd@1-10.0.0.63:22-10.0.0.1:39864.service - OpenSSH per-connection server daemon (10.0.0.1:39864). Sep 12 22:56:02.901233 systemd[1]: Starting docker.service - Docker Application Container Engine... Sep 12 22:56:02.934288 (dockerd)[1608]: docker.service: Referenced but unset environment variable evaluates to an empty string: DOCKER_CGROUPS, DOCKER_OPTS, DOCKER_OPT_BIP, DOCKER_OPT_IPMASQ, DOCKER_OPT_MTU Sep 12 22:56:03.034432 sshd[1607]: Accepted publickey for core from 10.0.0.1 port 39864 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:03.043067 sshd-session[1607]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:03.071964 systemd-logind[1452]: New session 2 of user core. Sep 12 22:56:03.085469 systemd[1]: Started session-2.scope - Session 2 of User core. Sep 12 22:56:03.352993 sshd[1611]: Connection closed by 10.0.0.1 port 39864 Sep 12 22:56:03.349964 sshd-session[1607]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:03.372352 systemd[1]: sshd@1-10.0.0.63:22-10.0.0.1:39864.service: Deactivated successfully. Sep 12 22:56:03.379975 systemd[1]: session-2.scope: Deactivated successfully. Sep 12 22:56:03.383442 systemd-logind[1452]: Session 2 logged out. Waiting for processes to exit. Sep 12 22:56:03.390755 systemd[1]: Started sshd@2-10.0.0.63:22-10.0.0.1:39872.service - OpenSSH per-connection server daemon (10.0.0.1:39872). Sep 12 22:56:03.403240 systemd-logind[1452]: Removed session 2. Sep 12 22:56:03.683337 sshd[1617]: Accepted publickey for core from 10.0.0.1 port 39872 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:03.688335 sshd-session[1617]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:03.697028 systemd-logind[1452]: New session 3 of user core. Sep 12 22:56:03.709506 systemd[1]: Started session-3.scope - Session 3 of User core. Sep 12 22:56:03.858028 sshd[1625]: Connection closed by 10.0.0.1 port 39872 Sep 12 22:56:03.858527 sshd-session[1617]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:03.867685 systemd[1]: sshd@2-10.0.0.63:22-10.0.0.1:39872.service: Deactivated successfully. Sep 12 22:56:03.870450 systemd[1]: session-3.scope: Deactivated successfully. Sep 12 22:56:03.873265 systemd-logind[1452]: Session 3 logged out. Waiting for processes to exit. Sep 12 22:56:03.875169 systemd-logind[1452]: Removed session 3. Sep 12 22:56:04.687944 dockerd[1608]: time="2025-09-12T22:56:04.686214703Z" level=info msg="Starting up" Sep 12 22:56:04.694845 dockerd[1608]: time="2025-09-12T22:56:04.693693672Z" level=info msg="OTEL tracing is not configured, using no-op tracer provider" Sep 12 22:56:04.798128 dockerd[1608]: time="2025-09-12T22:56:04.798066175Z" level=info msg="Creating a containerd client" address=/var/run/docker/libcontainerd/docker-containerd.sock timeout=1m0s Sep 12 22:56:05.019349 dockerd[1608]: time="2025-09-12T22:56:05.017150975Z" level=info msg="Loading containers: start." Sep 12 22:56:05.195406 kernel: Initializing XFRM netlink socket Sep 12 22:56:06.357094 systemd-networkd[1430]: docker0: Link UP Sep 12 22:56:06.368231 dockerd[1608]: time="2025-09-12T22:56:06.366592993Z" level=info msg="Loading containers: done." Sep 12 22:56:06.780927 dockerd[1608]: time="2025-09-12T22:56:06.777349495Z" level=warning msg="Not using native diff for overlay2, this may cause degraded performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled" storage-driver=overlay2 Sep 12 22:56:06.781828 dockerd[1608]: time="2025-09-12T22:56:06.781245222Z" level=info msg="Docker daemon" commit=6430e49a55babd9b8f4d08e70ecb2b68900770fe containerd-snapshotter=false storage-driver=overlay2 version=28.0.4 Sep 12 22:56:06.781828 dockerd[1608]: time="2025-09-12T22:56:06.781451709Z" level=info msg="Initializing buildkit" Sep 12 22:56:06.897584 dockerd[1608]: time="2025-09-12T22:56:06.897520411Z" level=info msg="Completed buildkit initialization" Sep 12 22:56:06.942925 dockerd[1608]: time="2025-09-12T22:56:06.942804371Z" level=info msg="Daemon has completed initialization" Sep 12 22:56:06.945489 dockerd[1608]: time="2025-09-12T22:56:06.943140411Z" level=info msg="API listen on /run/docker.sock" Sep 12 22:56:06.945822 systemd[1]: Started docker.service - Docker Application Container Engine. Sep 12 22:56:06.947091 etcd-wrapper[1578]: Error response from daemon: No such container: etcd-member Sep 12 22:56:07.028214 etcd-wrapper[1830]: Error response from daemon: No such container: etcd-member Sep 12 22:56:07.178753 etcd-wrapper[1851]: Unable to find image 'quay.io/coreos/etcd:v3.5.16' locally Sep 12 22:56:08.645912 etcd-wrapper[1851]: v3.5.16: Pulling from coreos/etcd Sep 12 22:56:08.946473 etcd-wrapper[1851]: 804c8aba2cc6: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: 2ae710cd8bfe: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: d462aa345367: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: 0f8b424aa0b9: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: d557676654e5: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: c8022d07192e: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: d858cbc252ad: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: 1069fc2daed1: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: b40161cd83fc: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: 5318d93a3a65: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: 307c1adadb60: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: fbb01d9e9dc9: Pulling fs layer Sep 12 22:56:08.946473 etcd-wrapper[1851]: c8022d07192e: Waiting Sep 12 22:56:08.946473 etcd-wrapper[1851]: d858cbc252ad: Waiting Sep 12 22:56:08.946473 etcd-wrapper[1851]: 1069fc2daed1: Waiting Sep 12 22:56:08.946473 etcd-wrapper[1851]: b40161cd83fc: Waiting Sep 12 22:56:08.946473 etcd-wrapper[1851]: 0f8b424aa0b9: Waiting Sep 12 22:56:08.948123 etcd-wrapper[1851]: fbfea02ac3cf: Pulling fs layer Sep 12 22:56:08.948123 etcd-wrapper[1851]: 8c26e4bf18e2: Pulling fs layer Sep 12 22:56:08.948123 etcd-wrapper[1851]: 1e59a65f8816: Pulling fs layer Sep 12 22:56:08.948329 etcd-wrapper[1851]: ffbd4ca5f0bd: Pulling fs layer Sep 12 22:56:08.948329 etcd-wrapper[1851]: 5318d93a3a65: Waiting Sep 12 22:56:08.948329 etcd-wrapper[1851]: 307c1adadb60: Waiting Sep 12 22:56:08.948329 etcd-wrapper[1851]: fbb01d9e9dc9: Waiting Sep 12 22:56:08.948329 etcd-wrapper[1851]: fbfea02ac3cf: Waiting Sep 12 22:56:08.948329 etcd-wrapper[1851]: 8c26e4bf18e2: Waiting Sep 12 22:56:08.948329 etcd-wrapper[1851]: 1e59a65f8816: Waiting Sep 12 22:56:08.948329 etcd-wrapper[1851]: ffbd4ca5f0bd: Waiting Sep 12 22:56:08.948329 etcd-wrapper[1851]: d557676654e5: Waiting Sep 12 22:56:09.265693 etcd-wrapper[1851]: 804c8aba2cc6: Verifying Checksum Sep 12 22:56:09.265693 etcd-wrapper[1851]: 804c8aba2cc6: Download complete Sep 12 22:56:09.288299 etcd-wrapper[1851]: 2ae710cd8bfe: Verifying Checksum Sep 12 22:56:09.288551 etcd-wrapper[1851]: 2ae710cd8bfe: Download complete Sep 12 22:56:09.403097 etcd-wrapper[1851]: d462aa345367: Verifying Checksum Sep 12 22:56:09.403097 etcd-wrapper[1851]: d462aa345367: Download complete Sep 12 22:56:09.435526 etcd-wrapper[1851]: 804c8aba2cc6: Pull complete Sep 12 22:56:09.520943 systemd[1]: var-lib-docker-overlay2-7d76c2cfd4921d3bbed5b48df960158c60cdf941bc6b5b657d81cb1656f19dda-merged.mount: Deactivated successfully. Sep 12 22:56:09.596769 etcd-wrapper[1851]: 2ae710cd8bfe: Pull complete Sep 12 22:56:09.607055 etcd-wrapper[1851]: 0f8b424aa0b9: Verifying Checksum Sep 12 22:56:09.607055 etcd-wrapper[1851]: 0f8b424aa0b9: Download complete Sep 12 22:56:09.718328 etcd-wrapper[1851]: c8022d07192e: Download complete Sep 12 22:56:09.733141 etcd-wrapper[1851]: d557676654e5: Verifying Checksum Sep 12 22:56:09.733141 etcd-wrapper[1851]: d557676654e5: Download complete Sep 12 22:56:09.955856 etcd-wrapper[1851]: d858cbc252ad: Verifying Checksum Sep 12 22:56:09.955856 etcd-wrapper[1851]: d858cbc252ad: Download complete Sep 12 22:56:10.060323 etcd-wrapper[1851]: b40161cd83fc: Verifying Checksum Sep 12 22:56:10.060323 etcd-wrapper[1851]: b40161cd83fc: Download complete Sep 12 22:56:10.103293 etcd-wrapper[1851]: 1069fc2daed1: Verifying Checksum Sep 12 22:56:10.103293 etcd-wrapper[1851]: 1069fc2daed1: Download complete Sep 12 22:56:10.347895 etcd-wrapper[1851]: 5318d93a3a65: Verifying Checksum Sep 12 22:56:10.348288 etcd-wrapper[1851]: 5318d93a3a65: Download complete Sep 12 22:56:10.384350 etcd-wrapper[1851]: 307c1adadb60: Verifying Checksum Sep 12 22:56:10.385217 etcd-wrapper[1851]: 307c1adadb60: Download complete Sep 12 22:56:10.828475 etcd-wrapper[1851]: fbb01d9e9dc9: Verifying Checksum Sep 12 22:56:10.828475 etcd-wrapper[1851]: fbb01d9e9dc9: Download complete Sep 12 22:56:10.842774 etcd-wrapper[1851]: 8c26e4bf18e2: Verifying Checksum Sep 12 22:56:10.842774 etcd-wrapper[1851]: 8c26e4bf18e2: Download complete Sep 12 22:56:11.032623 etcd-wrapper[1851]: fbfea02ac3cf: Verifying Checksum Sep 12 22:56:11.032623 etcd-wrapper[1851]: fbfea02ac3cf: Download complete Sep 12 22:56:11.169755 etcd-wrapper[1851]: 1e59a65f8816: Verifying Checksum Sep 12 22:56:11.169755 etcd-wrapper[1851]: 1e59a65f8816: Download complete Sep 12 22:56:11.182931 etcd-wrapper[1851]: ffbd4ca5f0bd: Verifying Checksum Sep 12 22:56:11.182931 etcd-wrapper[1851]: ffbd4ca5f0bd: Download complete Sep 12 22:56:11.828971 systemd[1]: var-lib-docker-overlay2-9a8f6da8a0c5416d18bda61762710e68e68fc24257f0cd7d4bbc89dca5c0b3ea-merged.mount: Deactivated successfully. Sep 12 22:56:12.030754 etcd-wrapper[1851]: d462aa345367: Pull complete Sep 12 22:56:12.152887 systemd[1]: var-lib-docker-overlay2-81483cde1e8cbb063c524b8411aeea074340aae3d335147050692dd0bafe4ffb-merged.mount: Deactivated successfully. Sep 12 22:56:12.213885 etcd-wrapper[1851]: 0f8b424aa0b9: Pull complete Sep 12 22:56:12.271551 systemd[1]: var-lib-docker-overlay2-665957a4de9e3fe41e937990624e55afc95e34aed6fcc997140dc366d700c7d0-merged.mount: Deactivated successfully. Sep 12 22:56:12.299658 etcd-wrapper[1851]: d557676654e5: Pull complete Sep 12 22:56:12.412709 etcd-wrapper[1851]: c8022d07192e: Pull complete Sep 12 22:56:12.477040 etcd-wrapper[1851]: d858cbc252ad: Pull complete Sep 12 22:56:12.557402 etcd-wrapper[1851]: 1069fc2daed1: Pull complete Sep 12 22:56:12.650406 etcd-wrapper[1851]: b40161cd83fc: Pull complete Sep 12 22:56:12.735492 etcd-wrapper[1851]: 5318d93a3a65: Pull complete Sep 12 22:56:12.864658 etcd-wrapper[1851]: 307c1adadb60: Pull complete Sep 12 22:56:14.087641 systemd[1]: Started sshd@3-10.0.0.63:22-10.0.0.1:48360.service - OpenSSH per-connection server daemon (10.0.0.1:48360). Sep 12 22:56:14.261505 sshd[1925]: Accepted publickey for core from 10.0.0.1 port 48360 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:14.270324 sshd-session[1925]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:14.288408 systemd-logind[1452]: New session 4 of user core. Sep 12 22:56:14.295720 systemd[1]: Started session-4.scope - Session 4 of User core. Sep 12 22:56:14.491145 sshd[1928]: Connection closed by 10.0.0.1 port 48360 Sep 12 22:56:14.493473 sshd-session[1925]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:14.527077 systemd[1]: var-lib-docker-overlay2-1275044f028124d5ec0941e6cd7793be9126dd103866c68402b0e52fe49d569b-merged.mount: Deactivated successfully. Sep 12 22:56:14.528253 systemd[1]: sshd@3-10.0.0.63:22-10.0.0.1:48360.service: Deactivated successfully. Sep 12 22:56:14.535288 systemd[1]: session-4.scope: Deactivated successfully. Sep 12 22:56:14.536660 systemd-logind[1452]: Session 4 logged out. Waiting for processes to exit. Sep 12 22:56:14.540368 systemd-logind[1452]: Removed session 4. Sep 12 22:56:14.541828 systemd[1]: Started sshd@4-10.0.0.63:22-10.0.0.1:48376.service - OpenSSH per-connection server daemon (10.0.0.1:48376). Sep 12 22:56:14.622286 sshd[1934]: Accepted publickey for core from 10.0.0.1 port 48376 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:14.624492 sshd-session[1934]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:14.660741 systemd-logind[1452]: New session 5 of user core. Sep 12 22:56:14.673988 systemd[1]: Started session-5.scope - Session 5 of User core. Sep 12 22:56:14.757169 sshd[1938]: Connection closed by 10.0.0.1 port 48376 Sep 12 22:56:14.757485 sshd-session[1934]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:14.769915 systemd[1]: sshd@4-10.0.0.63:22-10.0.0.1:48376.service: Deactivated successfully. Sep 12 22:56:14.775672 systemd[1]: session-5.scope: Deactivated successfully. Sep 12 22:56:14.779113 systemd-logind[1452]: Session 5 logged out. Waiting for processes to exit. Sep 12 22:56:14.786679 systemd-logind[1452]: Removed session 5. Sep 12 22:56:14.973116 etcd-wrapper[1851]: fbb01d9e9dc9: Pull complete Sep 12 22:56:15.634664 systemd[1]: var-lib-docker-overlay2-b71e270161577a84416a278fdf83af74742f70980221af63674ddd9dd63f68ca-merged.mount: Deactivated successfully. Sep 12 22:56:15.775144 etcd-wrapper[1851]: fbfea02ac3cf: Pull complete Sep 12 22:56:16.031126 kernel: hrtimer: interrupt took 4542521 ns Sep 12 22:56:16.489109 systemd[1]: var-lib-docker-overlay2-f5824c2e5ea4bb0b671fc3a34ffb4a2449e427f376682ac48bee9521c4808edd-merged.mount: Deactivated successfully. Sep 12 22:56:16.600124 etcd-wrapper[1851]: 8c26e4bf18e2: Pull complete Sep 12 22:56:16.661889 systemd[1]: var-lib-docker-overlay2-2b72c36a8e2a1ba933850fdf832d4ec45cef765798331802c8e34e4c7e8f53e5-merged.mount: Deactivated successfully. Sep 12 22:56:16.701676 etcd-wrapper[1851]: 1e59a65f8816: Pull complete Sep 12 22:56:16.760461 systemd[1]: var-lib-docker-overlay2-66dbeb5b3245aea43809ddf54680969c0a0ef1a1ee9dfc63c6110fefedb4ff4a-merged.mount: Deactivated successfully. Sep 12 22:56:16.876008 etcd-wrapper[1851]: ffbd4ca5f0bd: Pull complete Sep 12 22:56:16.932564 etcd-wrapper[1851]: Digest: sha256:d967d98a12dc220a1a290794711dba7eba04b8ce465e12b02383d1bfbb33e159 Sep 12 22:56:16.956972 etcd-wrapper[1851]: Status: Downloaded newer image for quay.io/coreos/etcd:v3.5.16 Sep 12 22:56:17.247351 containerd[1510]: time="2025-09-12T22:56:17.244710722Z" level=info msg="connecting to shim 0f2c67d999d2962b10d0dcf6c4e073b5ed876184a0be5f14f00a27e125c519c7" address="unix:///run/containerd/s/33b07da4e255546e8776b3210e74f8c94bc564b3694ecb9b36328654c8eb880a" namespace=moby protocol=ttrpc version=3 Sep 12 22:56:17.464534 systemd[1]: Started docker-0f2c67d999d2962b10d0dcf6c4e073b5ed876184a0be5f14f00a27e125c519c7.scope - libcontainer container 0f2c67d999d2962b10d0dcf6c4e073b5ed876184a0be5f14f00a27e125c519c7. Sep 12 22:56:17.570927 systemd-resolved[1340]: Failed to determine the local hostname and LLMNR/mDNS names, ignoring: No such device or address Sep 12 22:56:17.837384 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.836664Z","caller":"flags/flag.go:113","msg":"recognized and used environment variable","variable-name":"ETCD_DATA_DIR","variable-value":"/var/lib/etcd"} Sep 12 22:56:17.837384 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.836917Z","caller":"flags/flag.go:113","msg":"recognized and used environment variable","variable-name":"ETCD_NAME","variable-value":"3ad7b117211d4e308fb08802441a9118"} Sep 12 22:56:17.837384 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:56:17.836949Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_IMAGE_URL=quay.io/coreos/etcd"} Sep 12 22:56:17.837384 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:56:17.836967Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_IMAGE_TAG=v3.5.16"} Sep 12 22:56:17.837384 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:56:17.836974Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_USER=etcd"} Sep 12 22:56:17.837384 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:56:17.836980Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_SSL_DIR=/etc/ssl/certs"} Sep 12 22:56:17.838129 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:56:17.837006Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} Sep 12 22:56:17.838129 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.837487Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["/usr/local/bin/etcd","--listen-client-urls=http://0.0.0.0:2379","--advertise-client-urls=http://10.0.0.63:2379"]} Sep 12 22:56:17.838129 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:56:17.837571Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} Sep 12 22:56:17.838129 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.837583Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} Sep 12 22:56:17.848500 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.838996Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://0.0.0.0:2379"]} Sep 12 22:56:17.848500 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.841596Z","caller":"embed/etcd.go:311","msg":"starting an etcd server","etcd-version":"3.5.16","git-sha":"f20bbad","go-version":"go1.22.7","go-os":"linux","go-arch":"amd64","max-cpu-set":4,"max-cpu-available":4,"member-initialized":false,"name":"3ad7b117211d4e308fb08802441a9118","data-dir":"/var/lib/etcd","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/lib/etcd/member","force-new-cluster":false,"heartbeat-interval":"100ms","election-timeout":"1s","initial-election-tick-advance":true,"snapshot-count":100000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://10.0.0.63:2379"],"listen-client-urls":["http://0.0.0.0:2379"],"listen-metrics-urls":[],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"3ad7b117211d4e308fb08802441a9118=http://localhost:2380","initial-cluster-state":"new","initial-cluster-token":"etcd-cluster","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","compact-check-time-enabled":false,"compact-check-time-interval":"1m0s","auto-compaction-mode":"periodic","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":"","downgrade-check-interval":"5s"} Sep 12 22:56:17.858391 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.857565Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/var/lib/etcd/member/snap/db","took":"14.771798ms"} Sep 12 22:56:17.881776 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.877462Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} Sep 12 22:56:17.881776 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.877583Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} Sep 12 22:56:17.881776 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.877641Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} Sep 12 22:56:17.881776 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.877657Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} Sep 12 22:56:17.881776 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.877675Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} Sep 12 22:56:17.881776 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.877720Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} Sep 12 22:56:17.911156 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:56:17.905623Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} Sep 12 22:56:17.954755 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.954239Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} Sep 12 22:56:17.967643 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.963100Z","caller":"etcdserver/quota.go:94","msg":"enabled backend quota with default value","quota-name":"v3-applier","quota-size-bytes":2147483648,"quota-size":"2.1 GB"} Sep 12 22:56:17.970757 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.969538Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} Sep 12 22:56:17.970757 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.970071Z","caller":"etcdserver/server.go:757","msg":"started as single-node; fast-forwarding election ticks","local-member-id":"8e9e05c52164694d","forward-ticks":9,"forward-duration":"900ms","election-ticks":10,"election-timeout":"1s"} Sep 12 22:56:17.973341 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.970169Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"/var/lib/etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} Sep 12 22:56:17.973341 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.970241Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"/var/lib/etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} Sep 12 22:56:17.973341 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.970250Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"/var/lib/etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} Sep 12 22:56:17.973650 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.971018Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} Sep 12 22:56:17.973650 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.971520Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} Sep 12 22:56:17.973650 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.971595Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","added-peer-id":"8e9e05c52164694d","added-peer-peer-urls":["http://localhost:2380"]} Sep 12 22:56:17.974170 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.973896Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} Sep 12 22:56:17.974170 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.973957Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} Sep 12 22:56:17.974553 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:17.974300Z","caller":"embed/etcd.go:280","msg":"now serving peer/client/metrics","local-member-id":"8e9e05c52164694d","initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://10.0.0.63:2379"],"listen-client-urls":["http://0.0.0.0:2379"],"listen-metrics-urls":[]} Sep 12 22:56:18.680156 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.679372Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} Sep 12 22:56:18.680156 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.679457Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} Sep 12 22:56:18.680156 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.679505Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} Sep 12 22:56:18.680156 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.679521Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} Sep 12 22:56:18.680156 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.679530Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} Sep 12 22:56:18.680156 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.679541Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} Sep 12 22:56:18.680156 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.679550Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} Sep 12 22:56:18.684649 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.684004Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} Sep 12 22:56:18.694639 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.688502Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"} Sep 12 22:56:18.694639 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.689297Z","caller":"etcdserver/server.go:2140","msg":"published local member to cluster through raft","local-member-id":"8e9e05c52164694d","local-member-attributes":"{Name:3ad7b117211d4e308fb08802441a9118 ClientURLs:[http://10.0.0.63:2379]}","request-path":"/0/members/8e9e05c52164694d/attributes","cluster-id":"cdf818194e3a8c32","publish-timeout":"7s"} Sep 12 22:56:18.696990 systemd[1]: Started etcd-member.service - etcd (System Application Container). Sep 12 22:56:18.706461 systemd[1]: Reached target multi-user.target - Multi-User System. Sep 12 22:56:18.708370 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.693244Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} Sep 12 22:56:18.708370 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.695251Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} Sep 12 22:56:18.708370 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.695290Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} Sep 12 22:56:18.708370 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.693460Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} Sep 12 22:56:18.708370 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.695802Z","caller":"embed/serve.go:187","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"[::]:2379"} Sep 12 22:56:18.708370 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.689515Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} Sep 12 22:56:18.708370 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:56:18.696670Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} Sep 12 22:56:18.706645 systemd[1]: Startup finished in 5.114s (kernel) + 9.121s (initrd) + 24.942s (userspace) = 39.178s. Sep 12 22:56:24.792288 systemd[1]: Started sshd@5-10.0.0.63:22-10.0.0.1:41316.service - OpenSSH per-connection server daemon (10.0.0.1:41316). Sep 12 22:56:25.045929 sshd[2015]: Accepted publickey for core from 10.0.0.1 port 41316 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:25.045696 sshd-session[2015]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:25.063402 systemd-logind[1452]: New session 6 of user core. Sep 12 22:56:25.091503 systemd[1]: Started session-6.scope - Session 6 of User core. Sep 12 22:56:25.170860 sshd[2018]: Connection closed by 10.0.0.1 port 41316 Sep 12 22:56:25.169387 sshd-session[2015]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:25.185965 systemd[1]: sshd@5-10.0.0.63:22-10.0.0.1:41316.service: Deactivated successfully. Sep 12 22:56:25.192366 systemd[1]: session-6.scope: Deactivated successfully. Sep 12 22:56:25.194358 systemd-logind[1452]: Session 6 logged out. Waiting for processes to exit. Sep 12 22:56:25.201221 systemd[1]: Started sshd@6-10.0.0.63:22-10.0.0.1:41320.service - OpenSSH per-connection server daemon (10.0.0.1:41320). Sep 12 22:56:25.203257 systemd-logind[1452]: Removed session 6. Sep 12 22:56:25.354396 sshd[2024]: Accepted publickey for core from 10.0.0.1 port 41320 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:25.364831 sshd-session[2024]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:25.385665 systemd-logind[1452]: New session 7 of user core. Sep 12 22:56:25.400487 systemd[1]: Started session-7.scope - Session 7 of User core. Sep 12 22:56:25.485469 sshd[2027]: Connection closed by 10.0.0.1 port 41320 Sep 12 22:56:25.486129 sshd-session[2024]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:25.514974 systemd[1]: sshd@6-10.0.0.63:22-10.0.0.1:41320.service: Deactivated successfully. Sep 12 22:56:25.523820 systemd[1]: session-7.scope: Deactivated successfully. Sep 12 22:56:25.530571 systemd-logind[1452]: Session 7 logged out. Waiting for processes to exit. Sep 12 22:56:25.544488 systemd[1]: Started sshd@7-10.0.0.63:22-10.0.0.1:41332.service - OpenSSH per-connection server daemon (10.0.0.1:41332). Sep 12 22:56:25.551769 systemd-logind[1452]: Removed session 7. Sep 12 22:56:25.668387 sshd[2033]: Accepted publickey for core from 10.0.0.1 port 41332 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:25.675795 sshd-session[2033]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:25.698159 systemd-logind[1452]: New session 8 of user core. Sep 12 22:56:25.722613 systemd[1]: Started session-8.scope - Session 8 of User core. Sep 12 22:56:25.821064 sshd[2036]: Connection closed by 10.0.0.1 port 41332 Sep 12 22:56:25.821898 sshd-session[2033]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:25.837324 systemd[1]: sshd@7-10.0.0.63:22-10.0.0.1:41332.service: Deactivated successfully. Sep 12 22:56:25.842885 systemd[1]: session-8.scope: Deactivated successfully. Sep 12 22:56:25.846840 systemd-logind[1452]: Session 8 logged out. Waiting for processes to exit. Sep 12 22:56:25.855492 systemd[1]: Started sshd@8-10.0.0.63:22-10.0.0.1:41338.service - OpenSSH per-connection server daemon (10.0.0.1:41338). Sep 12 22:56:25.856887 systemd-logind[1452]: Removed session 8. Sep 12 22:56:25.932992 sshd[2042]: Accepted publickey for core from 10.0.0.1 port 41338 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:25.935495 sshd-session[2042]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:25.947603 systemd-logind[1452]: New session 9 of user core. Sep 12 22:56:25.956508 systemd[1]: Started session-9.scope - Session 9 of User core. Sep 12 22:56:26.042014 sshd[2045]: Connection closed by 10.0.0.1 port 41338 Sep 12 22:56:26.041530 sshd-session[2042]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:26.065066 systemd[1]: sshd@8-10.0.0.63:22-10.0.0.1:41338.service: Deactivated successfully. Sep 12 22:56:26.077933 systemd[1]: session-9.scope: Deactivated successfully. Sep 12 22:56:26.093135 systemd-logind[1452]: Session 9 logged out. Waiting for processes to exit. Sep 12 22:56:26.100508 systemd[1]: Started sshd@9-10.0.0.63:22-10.0.0.1:41346.service - OpenSSH per-connection server daemon (10.0.0.1:41346). Sep 12 22:56:26.104294 systemd-logind[1452]: Removed session 9. Sep 12 22:56:26.210459 sshd[2053]: Accepted publickey for core from 10.0.0.1 port 41346 ssh2: RSA SHA256:yYIxjrXQopGJXy2hREtBU3obW+AC5yBbC1aV8QR0JwE Sep 12 22:56:26.213467 sshd-session[2053]: pam_unix(sshd:session): session opened for user core(uid=500) by core(uid=0) Sep 12 22:56:26.232127 systemd-logind[1452]: New session 10 of user core. Sep 12 22:56:26.240722 systemd[1]: Started session-10.scope - Session 10 of User core. Sep 12 22:56:26.500327 sshd[2056]: Connection closed by 10.0.0.1 port 41346 Sep 12 22:56:26.505910 sshd-session[2053]: pam_unix(sshd:session): session closed for user core Sep 12 22:56:26.525194 systemd[1]: sshd@9-10.0.0.63:22-10.0.0.1:41346.service: Deactivated successfully. Sep 12 22:56:26.541971 systemd[1]: session-10.scope: Deactivated successfully. Sep 12 22:56:26.546128 systemd-logind[1452]: Session 10 logged out. Waiting for processes to exit. Sep 12 22:56:26.548072 systemd-logind[1452]: Removed session 10. Sep 12 22:56:45.542477 update_engine[1453]: I20250912 22:56:45.539085 1453 update_attempter.cc:509] Updating boot flags... Sep 12 22:58:24.287793 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:58:24.287139Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"125.530159ms","expected-duration":"100ms","prefix":"","request":"header: txn: success:> failure:<>>","response":"size:16"} Sep 12 22:58:24.287793 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.287312Z","caller":"traceutil/trace.go:171","msg":"trace[1108357738] linearizableReadLoop","detail":"{readStateIndex:246; appliedIndex:245; }","duration":"221.315813ms","start":"2025-09-12T22:58:24.065926Z","end":"2025-09-12T22:58:24.287242Z","steps":["trace[1108357738] 'read index received' (duration: 95.215609ms)","trace[1108357738] 'applied index is now lower than readState.Index' (duration: 126.099403ms)"],"step_count":2} Sep 12 22:58:24.287793 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.287300Z","caller":"traceutil/trace.go:171","msg":"trace[203154243] transaction","detail":"{read_only:false; response_revision:239; number_of_response:1; }","duration":"249.47346ms","start":"2025-09-12T22:58:24.037789Z","end":"2025-09-12T22:58:24.287263Z","steps":["trace[203154243] 'process raft request' (duration: 123.414024ms)","trace[203154243] 'compare' (duration: 125.403469ms)"],"step_count":2} Sep 12 22:58:24.287793 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:58:24.287448Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"221.517547ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/serviceaccounts/kube-system/pv-protection-controller\" ","response":"range_response_count:0 size:5"} Sep 12 22:58:24.288552 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.287480Z","caller":"traceutil/trace.go:171","msg":"trace[1256890430] range","detail":"{range_begin:/registry/serviceaccounts/kube-system/pv-protection-controller; range_end:; response_count:0; response_revision:239; }","duration":"221.552103ms","start":"2025-09-12T22:58:24.065915Z","end":"2025-09-12T22:58:24.287467Z","steps":["trace[1256890430] 'agreement among raft nodes before linearized reading' (duration: 221.440651ms)"],"step_count":1} Sep 12 22:58:24.311780 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.311368Z","caller":"traceutil/trace.go:171","msg":"trace[510284043] transaction","detail":"{read_only:false; response_revision:241; number_of_response:1; }","duration":"235.692985ms","start":"2025-09-12T22:58:24.075653Z","end":"2025-09-12T22:58:24.311346Z","steps":["trace[510284043] 'process raft request' (duration: 235.617061ms)"],"step_count":1} Sep 12 22:58:24.311780 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.311419Z","caller":"traceutil/trace.go:171","msg":"trace[1732104508] transaction","detail":"{read_only:false; number_of_response:0; response_revision:239; }","duration":"235.804265ms","start":"2025-09-12T22:58:24.075605Z","end":"2025-09-12T22:58:24.311410Z","steps":["trace[1732104508] 'process raft request' (duration: 235.519875ms)"],"step_count":1} Sep 12 22:58:24.311780 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.311445Z","caller":"traceutil/trace.go:171","msg":"trace[1667791666] transaction","detail":"{read_only:false; number_of_response:0; response_revision:241; }","duration":"175.043515ms","start":"2025-09-12T22:58:24.136393Z","end":"2025-09-12T22:58:24.311437Z","steps":["trace[1667791666] 'process raft request' (duration: 174.897487ms)"],"step_count":1} Sep 12 22:58:24.311780 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.311465Z","caller":"traceutil/trace.go:171","msg":"trace[1146631799] transaction","detail":"{read_only:false; response_revision:240; number_of_response:1; }","duration":"235.850293ms","start":"2025-09-12T22:58:24.075605Z","end":"2025-09-12T22:58:24.311456Z","steps":["trace[1146631799] 'process raft request' (duration: 235.618301ms)"],"step_count":1} Sep 12 22:58:24.311780 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.311491Z","caller":"traceutil/trace.go:171","msg":"trace[615026584] transaction","detail":"{read_only:false; response_revision:242; number_of_response:1; }","duration":"174.234295ms","start":"2025-09-12T22:58:24.137251Z","end":"2025-09-12T22:58:24.311485Z","steps":["trace[615026584] 'process raft request' (duration: 174.055846ms)"],"step_count":1} Sep 12 22:58:24.991500 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:58:24.991038Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"161.978328ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/serviceaccounts/kube-system/namespace-controller\" ","response":"range_response_count:1 size:205"} Sep 12 22:58:24.991500 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.991105Z","caller":"traceutil/trace.go:171","msg":"trace[342254993] range","detail":"{range_begin:/registry/serviceaccounts/kube-system/namespace-controller; range_end:; response_count:1; response_revision:260; }","duration":"162.072286ms","start":"2025-09-12T22:58:24.829018Z","end":"2025-09-12T22:58:24.991091Z","steps":["trace[342254993] 'range keys from in-memory index tree' (duration: 161.857778ms)"],"step_count":1} Sep 12 22:58:24.991500 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:58:24.991131Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"174.036989ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:5"} Sep 12 22:58:24.991500 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:24.991224Z","caller":"traceutil/trace.go:171","msg":"trace[854389345] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:260; }","duration":"174.172315ms","start":"2025-09-12T22:58:24.817033Z","end":"2025-09-12T22:58:24.991205Z","steps":["trace[854389345] 'range keys from in-memory index tree' (duration: 173.82252ms)"],"step_count":1} Sep 12 22:58:25.324554 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:25.324091Z","caller":"traceutil/trace.go:171","msg":"trace[714501202] transaction","detail":"{read_only:false; response_revision:269; number_of_response:1; }","duration":"144.948262ms","start":"2025-09-12T22:58:25.179123Z","end":"2025-09-12T22:58:25.324072Z","steps":["trace[714501202] 'process raft request' (duration: 144.907204ms)"],"step_count":1} Sep 12 22:58:25.324554 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:25.324143Z","caller":"traceutil/trace.go:171","msg":"trace[430893276] transaction","detail":"{read_only:false; response_revision:268; number_of_response:1; }","duration":"164.745364ms","start":"2025-09-12T22:58:25.159384Z","end":"2025-09-12T22:58:25.324129Z","steps":["trace[430893276] 'process raft request' (duration: 161.233745ms)"],"step_count":1} Sep 12 22:58:27.595625 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:27.595167Z","caller":"traceutil/trace.go:171","msg":"trace[733592402] linearizableReadLoop","detail":"{readStateIndex:308; appliedIndex:307; }","duration":"166.567369ms","start":"2025-09-12T22:58:27.428581Z","end":"2025-09-12T22:58:27.595148Z","steps":["trace[733592402] 'read index received' (duration: 166.456297ms)","trace[733592402] 'applied index is now lower than readState.Index' (duration: 110.591µs)"],"step_count":2} Sep 12 22:58:27.595625 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:27.595232Z","caller":"traceutil/trace.go:171","msg":"trace[25554026] transaction","detail":"{read_only:false; response_revision:298; number_of_response:1; }","duration":"186.468818ms","start":"2025-09-12T22:58:27.408745Z","end":"2025-09-12T22:58:27.595214Z","steps":["trace[25554026] 'process raft request' (duration: 186.302732ms)"],"step_count":1} Sep 12 22:58:27.595625 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:58:27.595348Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"166.728286ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/namespaces/kube-system\" ","response":"range_response_count:1 size:351"} Sep 12 22:58:27.595625 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:27.595449Z","caller":"traceutil/trace.go:171","msg":"trace[183666526] range","detail":"{range_begin:/registry/namespaces/kube-system; range_end:; response_count:1; response_revision:298; }","duration":"166.878921ms","start":"2025-09-12T22:58:27.428545Z","end":"2025-09-12T22:58:27.595424Z","steps":["trace[183666526] 'agreement among raft nodes before linearized reading' (duration: 166.699149ms)"],"step_count":1} Sep 12 22:58:27.871938 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:58:27.871510Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"133.601337ms","expected-duration":"100ms","prefix":"","request":"header: txn: success:> failure:<>>","response":"size:16"} Sep 12 22:58:27.871938 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:27.871585Z","caller":"traceutil/trace.go:171","msg":"trace[816997352] transaction","detail":"{read_only:false; response_revision:300; number_of_response:1; }","duration":"216.492119ms","start":"2025-09-12T22:58:27.655080Z","end":"2025-09-12T22:58:27.871573Z","steps":["trace[816997352] 'process raft request' (duration: 82.788528ms)","trace[816997352] 'compare' (duration: 133.461812ms)"],"step_count":2} Sep 12 22:58:54.338100 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:54.337565Z","caller":"traceutil/trace.go:171","msg":"trace[1222318829] transaction","detail":"{read_only:false; response_revision:455; number_of_response:1; }","duration":"162.777355ms","start":"2025-09-12T22:58:54.174764Z","end":"2025-09-12T22:58:54.337542Z","steps":["trace[1222318829] 'process raft request' (duration: 162.659802ms)"],"step_count":1} Sep 12 22:58:54.356365 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:54.356011Z","caller":"traceutil/trace.go:171","msg":"trace[1670846073] transaction","detail":"{read_only:false; response_revision:456; number_of_response:1; }","duration":"158.011767ms","start":"2025-09-12T22:58:54.197974Z","end":"2025-09-12T22:58:54.355985Z","steps":["trace[1670846073] 'process raft request' (duration: 157.855282ms)"],"step_count":1} Sep 12 22:58:55.932099 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:55.931645Z","caller":"traceutil/trace.go:171","msg":"trace[1376116250] transaction","detail":"{read_only:false; response_revision:469; number_of_response:1; }","duration":"169.677192ms","start":"2025-09-12T22:58:55.761950Z","end":"2025-09-12T22:58:55.931627Z","steps":["trace[1376116250] 'process raft request' (duration: 75.534386ms)","trace[1376116250] 'compare' (duration: 94.002491ms)"],"step_count":2} Sep 12 22:58:55.932099 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:55.931638Z","caller":"traceutil/trace.go:171","msg":"trace[1324035255] linearizableReadLoop","detail":"{readStateIndex:485; appliedIndex:484; }","duration":"148.221003ms","start":"2025-09-12T22:58:55.783391Z","end":"2025-09-12T22:58:55.931612Z","steps":["trace[1324035255] 'read index received' (duration: 54.096542ms)","trace[1324035255] 'applied index is now lower than readState.Index' (duration: 94.12366ms)"],"step_count":2} Sep 12 22:58:55.932099 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:58:55.931770Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"148.365006ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/csinodes/10.0.0.84\" ","response":"range_response_count:0 size:5"} Sep 12 22:58:55.932914 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:55.931820Z","caller":"traceutil/trace.go:171","msg":"trace[1660957974] range","detail":"{range_begin:/registry/csinodes/10.0.0.84; range_end:; response_count:0; response_revision:469; }","duration":"148.585794ms","start":"2025-09-12T22:58:55.783223Z","end":"2025-09-12T22:58:55.931808Z","steps":["trace[1660957974] 'agreement among raft nodes before linearized reading' (duration: 148.456871ms)"],"step_count":1} Sep 12 22:58:55.995766 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:58:55.994701Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"179.509711ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:5"} Sep 12 22:58:55.995766 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:58:55.994819Z","caller":"traceutil/trace.go:171","msg":"trace[1672785435] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:470; }","duration":"179.651249ms","start":"2025-09-12T22:58:55.815131Z","end":"2025-09-12T22:58:55.994782Z","steps":["trace[1672785435] 'agreement among raft nodes before linearized reading' (duration: 179.523597ms)"],"step_count":1} Sep 12 22:59:04.464100 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:04.463637Z","caller":"traceutil/trace.go:171","msg":"trace[2092079834] transaction","detail":"{read_only:false; response_revision:516; number_of_response:1; }","duration":"137.251945ms","start":"2025-09-12T22:59:04.326364Z","end":"2025-09-12T22:59:04.463616Z","steps":["trace[2092079834] 'process raft request' (duration: 137.025949ms)"],"step_count":1} Sep 12 22:59:04.564669 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:04.564262Z","caller":"traceutil/trace.go:171","msg":"trace[465467406] transaction","detail":"{read_only:false; response_revision:517; number_of_response:1; }","duration":"180.984424ms","start":"2025-09-12T22:59:04.383242Z","end":"2025-09-12T22:59:04.564227Z","steps":["trace[465467406] 'process raft request' (duration: 113.121849ms)","trace[465467406] 'compare' (duration: 67.735134ms)"],"step_count":2} Sep 12 22:59:08.688688 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:08.688364Z","caller":"traceutil/trace.go:171","msg":"trace[2039056359] transaction","detail":"{read_only:false; response_revision:532; number_of_response:1; }","duration":"114.149064ms","start":"2025-09-12T22:59:08.574193Z","end":"2025-09-12T22:59:08.688342Z","steps":["trace[2039056359] 'process raft request' (duration: 113.296473ms)"],"step_count":1} Sep 12 22:59:09.714631 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:09.714246Z","caller":"traceutil/trace.go:171","msg":"trace[1769765343] transaction","detail":"{read_only:false; response_revision:535; number_of_response:1; }","duration":"385.156892ms","start":"2025-09-12T22:59:09.329068Z","end":"2025-09-12T22:59:09.714225Z","steps":["trace[1769765343] 'process raft request' (duration: 306.056634ms)","trace[1769765343] 'compare' (duration: 78.987785ms)"],"step_count":2} Sep 12 22:59:09.715262 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:09.714538Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:09.329043Z","time spent":"385.26138ms","remote":"10.0.0.71:55730","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":7680,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:16.261006 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:16.259258Z","caller":"traceutil/trace.go:171","msg":"trace[956643025] transaction","detail":"{read_only:false; response_revision:566; number_of_response:1; }","duration":"131.945793ms","start":"2025-09-12T22:59:16.127261Z","end":"2025-09-12T22:59:16.259206Z","steps":["trace[956643025] 'process raft request' (duration: 131.80105ms)"],"step_count":1} Sep 12 22:59:33.453823 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:33.453199Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"719.443407ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/masterleases/10.0.0.71\" ","response":"range_response_count:1 size:125"} Sep 12 22:59:33.454553 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:33.453883Z","caller":"traceutil/trace.go:171","msg":"trace[342973558] range","detail":"{range_begin:/registry/masterleases/10.0.0.71; range_end:; response_count:1; response_revision:612; }","duration":"720.163055ms","start":"2025-09-12T22:59:32.733701Z","end":"2025-09-12T22:59:33.453864Z","steps":["trace[342973558] 'range keys from in-memory index tree' (duration: 719.344571ms)"],"step_count":1} Sep 12 22:59:33.454553 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:33.453929Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:32.733654Z","time spent":"720.264878ms","remote":"10.0.0.71:55546","response type":"/etcdserverpb.KV/Range","request count":0,"request size":34,"response count":1,"response size":149,"request content":"key:\"/registry/masterleases/10.0.0.71\" "} Sep 12 22:59:33.454553 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:33.453403Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"562.275439ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/pods/default/test-pod-1\" ","response":"range_response_count:0 size:5"} Sep 12 22:59:33.454553 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:33.454005Z","caller":"traceutil/trace.go:171","msg":"trace[1252310867] range","detail":"{range_begin:/registry/pods/default/test-pod-1; range_end:; response_count:0; response_revision:612; }","duration":"562.931968ms","start":"2025-09-12T22:59:32.891068Z","end":"2025-09-12T22:59:33.454000Z","steps":["trace[1252310867] 'range keys from in-memory index tree' (duration: 562.219183ms)"],"step_count":1} Sep 12 22:59:33.454553 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:33.454022Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:32.891045Z","time spent":"562.971412ms","remote":"10.0.0.71:55730","response type":"/etcdserverpb.KV/Range","request count":0,"request size":35,"response count":0,"response size":29,"request content":"key:\"/registry/pods/default/test-pod-1\" "} Sep 12 22:59:33.454739 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:33.453583Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"145.505342ms","expected-duration":"100ms","prefix":"","request":"header: txn: success:> failure: >>","response":"size:16"} Sep 12 22:59:33.454739 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:33.454480Z","caller":"traceutil/trace.go:171","msg":"trace[588978072] transaction","detail":"{read_only:false; response_revision:613; number_of_response:1; }","duration":"535.732176ms","start":"2025-09-12T22:59:32.918731Z","end":"2025-09-12T22:59:33.454463Z","steps":["trace[588978072] 'process raft request' (duration: 389.271541ms)","trace[588978072] 'compare' (duration: 145.265148ms)"],"step_count":2} Sep 12 22:59:33.455003 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:33.454581Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:32.918709Z","time spent":"535.79344ms","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":492,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:34.444904 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:34.444468Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:33.842343Z","time spent":"602.115679ms","remote":"10.0.0.71:42446","response type":"/etcdserverpb.Maintenance/Status","request count":-1,"request size":-1,"response count":-1,"response size":-1,"request content":""} Sep 12 22:59:34.445242 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:34.444636Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"823.590439ms","expected-duration":"100ms","prefix":"","request":"header: txn: success:> failure: >>","response":"size:16"} Sep 12 22:59:34.445242 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:34.444699Z","caller":"traceutil/trace.go:171","msg":"trace[2146160931] transaction","detail":"{read_only:false; response_revision:614; number_of_response:1; }","duration":"1.470743159s","start":"2025-09-12T22:59:32.973943Z","end":"2025-09-12T22:59:34.444686Z","steps":["trace[2146160931] 'process raft request' (duration: 647.038384ms)","trace[2146160931] 'compare' (duration: 823.495831ms)"],"step_count":2} Sep 12 22:59:34.445242 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:34.444759Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:32.973922Z","time spent":"1.470814073s","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":674,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:35.512412 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:35.511995Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"893.135575ms","expected-duration":"100ms","prefix":"","request":"header: lease_grant:","response":"size:41"} Sep 12 22:59:35.513417 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:35.512221Z","caller":"traceutil/trace.go:171","msg":"trace[1248435492] transaction","detail":"{read_only:false; response_revision:616; number_of_response:1; }","duration":"1.061825111s","start":"2025-09-12T22:59:34.450382Z","end":"2025-09-12T22:59:35.512207Z","steps":["trace[1248435492] 'process raft request' (duration: 1.061772972s)"],"step_count":1} Sep 12 22:59:35.513417 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:35.512266Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:33.456316Z","time spent":"2.05594655s","remote":"10.0.0.71:55546","response type":"/etcdserverpb.Lease/LeaseGrant","request count":-1,"request size":-1,"response count":-1,"response size":-1,"request content":""} Sep 12 22:59:35.513417 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:35.512314Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:34.450366Z","time spent":"1.061896686s","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":465,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:35.513417 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:35.512356Z","caller":"traceutil/trace.go:171","msg":"trace[1612928276] linearizableReadLoop","detail":"{readStateIndex:642; appliedIndex:639; }","duration":"1.902904104s","start":"2025-09-12T22:59:33.609446Z","end":"2025-09-12T22:59:35.512350Z","steps":["trace[1612928276] 'read index received' (duration: 11.549396ms)","trace[1612928276] 'applied index is now lower than readState.Index' (duration: 1.891354227s)"],"step_count":2} Sep 12 22:59:35.513657 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:35.512222Z","caller":"traceutil/trace.go:171","msg":"trace[347523892] transaction","detail":"{read_only:false; response_revision:615; number_of_response:1; }","duration":"2.050992431s","start":"2025-09-12T22:59:33.461215Z","end":"2025-09-12T22:59:35.512207Z","steps":["trace[347523892] 'process raft request' (duration: 2.050865441s)"],"step_count":1} Sep 12 22:59:35.513657 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:35.512447Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"1.902998482s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/prioritylevelconfigurations/\" range_end:\"/registry/prioritylevelconfigurations0\" count_only:true ","response":"range_response_count:0 size:7"} Sep 12 22:59:35.513657 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:35.512465Z","caller":"traceutil/trace.go:171","msg":"trace[532811508] range","detail":"{range_begin:/registry/prioritylevelconfigurations/; range_end:/registry/prioritylevelconfigurations0; response_count:0; response_revision:616; }","duration":"1.903049069s","start":"2025-09-12T22:59:33.609410Z","end":"2025-09-12T22:59:35.512459Z","steps":["trace[532811508] 'agreement among raft nodes before linearized reading' (duration: 1.902974007s)"],"step_count":1} Sep 12 22:59:35.513657 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:35.512482Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:33.609389Z","time spent":"1.903086559s","remote":"10.0.0.71:55964","response type":"/etcdserverpb.KV/Range","request count":0,"request size":82,"response count":8,"response size":31,"request content":"key:\"/registry/prioritylevelconfigurations/\" range_end:\"/registry/prioritylevelconfigurations0\" count_only:true "} Sep 12 22:59:35.513794 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:35.512488Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:33.461195Z","time spent":"2.05120361s","remote":"10.0.0.71:55730","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":1867,"response count":0,"response size":40,"request content":"compare: success:> failure:<>"} Sep 12 22:59:35.815104 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:35.814574Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"2.000711647s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"","error":"context canceled"} Sep 12 22:59:35.815104 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:35.814652Z","caller":"traceutil/trace.go:171","msg":"trace[1393305400] range","detail":"{range_begin:/registry/health; range_end:; }","duration":"2.000837475s","start":"2025-09-12T22:59:33.813799Z","end":"2025-09-12T22:59:35.814636Z","steps":["trace[1393305400] 'agreement among raft nodes before linearized reading' (duration: 2.000738147s)"],"step_count":1} Sep 12 22:59:35.815104 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:35.814695Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:33.813781Z","time spent":"2.000904882s","remote":"10.0.0.71:55514","response type":"/etcdserverpb.KV/Range","request count":0,"request size":18,"response count":0,"response size":0,"request content":"key:\"/registry/health\" "} Sep 12 22:59:37.815705 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:37.815063Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"2.000325328s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"","error":"context canceled"} Sep 12 22:59:37.815705 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:37.815138Z","caller":"traceutil/trace.go:171","msg":"trace[974658769] range","detail":"{range_begin:/registry/health; range_end:; }","duration":"2.000448992s","start":"2025-09-12T22:59:35.814671Z","end":"2025-09-12T22:59:37.815120Z","steps":["trace[974658769] 'agreement among raft nodes before linearized reading' (duration: 2.000347751s)"],"step_count":1} Sep 12 22:59:37.815705 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:37.815422Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.814653Z","time spent":"2.000517891s","remote":"10.0.0.71:55522","response type":"/etcdserverpb.KV/Range","request count":0,"request size":18,"response count":0,"response size":0,"request content":"key:\"/registry/health\" "} Sep 12 22:59:39.822889 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.822506Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"2.000324943s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"","error":"context canceled"} Sep 12 22:59:39.822889 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:39.822571Z","caller":"traceutil/trace.go:171","msg":"trace[1537679312] range","detail":"{range_begin:/registry/health; range_end:; }","duration":"2.000524951s","start":"2025-09-12T22:59:37.822032Z","end":"2025-09-12T22:59:39.822557Z","steps":["trace[1537679312] 'agreement among raft nodes before linearized reading' (duration: 2.000440863s)"],"step_count":1} Sep 12 22:59:39.822889 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.822603Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:37.821960Z","time spent":"2.000635018s","remote":"10.0.0.71:55514","response type":"/etcdserverpb.KV/Range","request count":0,"request size":18,"response count":0,"response size":0,"request content":"key:\"/registry/health\" "} Sep 12 22:59:39.855946 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.855483Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"4.032549602s","expected-duration":"100ms","prefix":"","request":"header: txn: success:> failure: >>","response":"size:16"} Sep 12 22:59:39.855946 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:39.855567Z","caller":"traceutil/trace.go:171","msg":"trace[842949249] linearizableReadLoop","detail":"{readStateIndex:644; appliedIndex:643; }","duration":"4.343188211s","start":"2025-09-12T22:59:35.512366Z","end":"2025-09-12T22:59:39.855555Z","steps":["trace[842949249] 'read index received' (duration: 310.512972ms)","trace[842949249] 'applied index is now lower than readState.Index' (duration: 4.032674288s)"],"step_count":2} Sep 12 22:59:39.855946 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:39.855628Z","caller":"traceutil/trace.go:171","msg":"trace[835911024] transaction","detail":"{read_only:false; response_revision:617; number_of_response:1; }","duration":"4.394608004s","start":"2025-09-12T22:59:35.460983Z","end":"2025-09-12T22:59:39.855591Z","steps":["trace[835911024] 'process raft request' (duration: 361.885035ms)","trace[835911024] 'compare' (duration: 4.032435486s)"],"step_count":2} Sep 12 22:59:39.856220 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.855840Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.460963Z","time spent":"4.394772344s","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":492,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:39.880104 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.879937Z","caller":"wal/wal.go:805","msg":"slow fdatasync","took":"4.057116545s","expected-duration":"1s"} Sep 12 22:59:39.880750 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:39.880305Z","caller":"traceutil/trace.go:171","msg":"trace[202215304] transaction","detail":"{read_only:false; response_revision:618; number_of_response:1; }","duration":"4.367030807s","start":"2025-09-12T22:59:35.513259Z","end":"2025-09-12T22:59:39.880290Z","steps":["trace[202215304] 'process raft request' (duration: 4.366810992s)"],"step_count":1} Sep 12 22:59:39.880750 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:39.880318Z","caller":"traceutil/trace.go:171","msg":"trace[2132860824] transaction","detail":"{read_only:false; response_revision:619; number_of_response:1; }","duration":"4.363104439s","start":"2025-09-12T22:59:35.517202Z","end":"2025-09-12T22:59:39.880307Z","steps":["trace[2132860824] 'process raft request' (duration: 4.363010512s)"],"step_count":1} Sep 12 22:59:39.880750 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:39.880340Z","caller":"traceutil/trace.go:171","msg":"trace[529010384] transaction","detail":"{read_only:false; response_revision:621; number_of_response:1; }","duration":"4.355745131s","start":"2025-09-12T22:59:35.524574Z","end":"2025-09-12T22:59:39.880319Z","steps":["trace[529010384] 'process raft request' (duration: 4.355709514s)"],"step_count":1} Sep 12 22:59:39.880750 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.880376Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.517166Z","time spent":"4.363176826s","remote":"10.0.0.71:55614","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":770,"response count":0,"response size":40,"request content":"compare: success:> failure:<>"} Sep 12 22:59:39.880937 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.880388Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.513229Z","time spent":"4.36710624s","remote":"10.0.0.71:55546","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":110,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:39.880937 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:39.880453Z","caller":"traceutil/trace.go:171","msg":"trace[1648585319] transaction","detail":"{read_only:false; response_revision:620; number_of_response:1; }","duration":"4.36239492s","start":"2025-09-12T22:59:35.518052Z","end":"2025-09-12T22:59:39.880447Z","steps":["trace[1648585319] 'process raft request' (duration: 4.362202327s)"],"step_count":1} Sep 12 22:59:39.880937 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.880458Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.524563Z","time spent":"4.355835772s","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":525,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:39.881049 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:39.880486Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.518034Z","time spent":"4.362432961s","remote":"10.0.0.71:55730","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":2335,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:40.045850 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045279Z","caller":"traceutil/trace.go:171","msg":"trace[1114322547] linearizableReadLoop","detail":"{readStateIndex:650; appliedIndex:644; }","duration":"189.674915ms","start":"2025-09-12T22:59:39.855585Z","end":"2025-09-12T22:59:40.045260Z","steps":["trace[1114322547] 'read index received' (duration: 24.556644ms)","trace[1114322547] 'applied index is now lower than readState.Index' (duration: 165.11771ms)"],"step_count":2} Sep 12 22:59:40.045850 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045454Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"4.110458496s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/csidrivers/\" range_end:\"/registry/csidrivers0\" count_only:true ","response":"range_response_count:0 size:5"} Sep 12 22:59:40.046621 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045556Z","caller":"traceutil/trace.go:171","msg":"trace[1848754503] range","detail":"{range_begin:/registry/csidrivers/; range_end:/registry/csidrivers0; response_count:0; response_revision:623; }","duration":"4.110611957s","start":"2025-09-12T22:59:35.934937Z","end":"2025-09-12T22:59:40.045549Z","steps":["trace[1848754503] 'agreement among raft nodes before linearized reading' (duration: 4.110435945s)"],"step_count":1} Sep 12 22:59:40.046621 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045589Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.934918Z","time spent":"4.110660339s","remote":"10.0.0.71:55944","response type":"/etcdserverpb.KV/Range","request count":0,"request size":48,"response count":0,"response size":29,"request content":"key:\"/registry/csidrivers/\" range_end:\"/registry/csidrivers0\" count_only:true "} Sep 12 22:59:40.046621 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045596Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"3.534306811s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/prioritylevelconfigurations/\" range_end:\"/registry/prioritylevelconfigurations0\" count_only:true ","response":"range_response_count:0 size:7"} Sep 12 22:59:40.046621 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045656Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"4.2072457s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/cronjobs/\" range_end:\"/registry/cronjobs0\" count_only:true ","response":"range_response_count:0 size:5"} Sep 12 22:59:40.046831 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045655Z","caller":"traceutil/trace.go:171","msg":"trace[538192959] range","detail":"{range_begin:/registry/prioritylevelconfigurations/; range_end:/registry/prioritylevelconfigurations0; response_count:0; response_revision:623; }","duration":"3.534421717s","start":"2025-09-12T22:59:36.511219Z","end":"2025-09-12T22:59:40.045641Z","steps":["trace[538192959] 'agreement among raft nodes before linearized reading' (duration: 3.534303424s)"],"step_count":1} Sep 12 22:59:40.046831 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045673Z","caller":"traceutil/trace.go:171","msg":"trace[182971831] range","detail":"{range_begin:/registry/cronjobs/; range_end:/registry/cronjobs0; response_count:0; response_revision:623; }","duration":"4.207284975s","start":"2025-09-12T22:59:35.838384Z","end":"2025-09-12T22:59:40.045669Z","steps":["trace[182971831] 'agreement among raft nodes before linearized reading' (duration: 4.207258876s)"],"step_count":1} Sep 12 22:59:40.046831 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045690Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.838370Z","time spent":"4.207314381s","remote":"10.0.0.71:55786","response type":"/etcdserverpb.KV/Range","request count":0,"request size":44,"response count":0,"response size":29,"request content":"key:\"/registry/cronjobs/\" range_end:\"/registry/cronjobs0\" count_only:true "} Sep 12 22:59:40.046831 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045642Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"4.076504035s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/events/kube-system/kube-scheduler-localhost.1864ab1f059d5f4f\" ","response":"range_response_count:1 size:817"} Sep 12 22:59:40.046831 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045725Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"4.529966881s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/persistentvolumeclaims/default/test-dynamic-volume-claim\" ","response":"range_response_count:0 size:5"} Sep 12 22:59:40.047993 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045743Z","caller":"traceutil/trace.go:171","msg":"trace[1490522429] range","detail":"{range_begin:/registry/persistentvolumeclaims/default/test-dynamic-volume-claim; range_end:; response_count:0; response_revision:623; }","duration":"4.530000604s","start":"2025-09-12T22:59:35.515736Z","end":"2025-09-12T22:59:40.045736Z","steps":["trace[1490522429] 'agreement among raft nodes before linearized reading' (duration: 4.529979995s)"],"step_count":1} Sep 12 22:59:40.047993 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045762Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.515722Z","time spent":"4.5300353s","remote":"10.0.0.71:55694","response type":"/etcdserverpb.KV/Range","request count":0,"request size":68,"response count":0,"response size":29,"request content":"key:\"/registry/persistentvolumeclaims/default/test-dynamic-volume-claim\" "} Sep 12 22:59:40.047993 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045763Z","caller":"traceutil/trace.go:171","msg":"trace[2080534597] range","detail":"{range_begin:/registry/events/kube-system/kube-scheduler-localhost.1864ab1f059d5f4f; range_end:; response_count:1; response_revision:623; }","duration":"4.076651603s","start":"2025-09-12T22:59:35.969073Z","end":"2025-09-12T22:59:40.045724Z","steps":["trace[2080534597] 'agreement among raft nodes before linearized reading' (duration: 4.076271646s)"],"step_count":1} Sep 12 22:59:40.047993 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045809Z","caller":"traceutil/trace.go:171","msg":"trace[1205245481] transaction","detail":"{read_only:false; response_revision:623; number_of_response:1; }","duration":"2.527993991s","start":"2025-09-12T22:59:37.517805Z","end":"2025-09-12T22:59:40.045799Z","steps":["trace[1205245481] 'process raft request' (duration: 2.527423124s)"],"step_count":1} Sep 12 22:59:40.048218 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045816Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"164.000131ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/services/endpoints/default/kubernetes\" ","response":"range_response_count:1 size:417"} Sep 12 22:59:40.048218 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045832Z","caller":"traceutil/trace.go:171","msg":"trace[704211012] range","detail":"{range_begin:/registry/services/endpoints/default/kubernetes; range_end:; response_count:1; response_revision:623; }","duration":"164.015491ms","start":"2025-09-12T22:59:39.881812Z","end":"2025-09-12T22:59:40.045827Z","steps":["trace[704211012] 'agreement among raft nodes before linearized reading' (duration: 163.984923ms)"],"step_count":1} Sep 12 22:59:40.048218 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045870Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:37.517783Z","time spent":"2.528044928s","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":465,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:40.048218 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.045967Z","caller":"traceutil/trace.go:171","msg":"trace[1193063027] transaction","detail":"{read_only:false; response_revision:622; number_of_response:1; }","duration":"3.821549235s","start":"2025-09-12T22:59:36.224410Z","end":"2025-09-12T22:59:40.045959Z","steps":["trace[1193063027] 'process raft request' (duration: 3.733543994s)","trace[1193063027] 'compare' (duration: 87.137724ms)"],"step_count":2} Sep 12 22:59:40.048447 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045963Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"223.321594ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:5"} Sep 12 22:59:40.048447 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.046021Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:36.224387Z","time spent":"3.82159477s","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":524,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:40.048447 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.046031Z","caller":"traceutil/trace.go:171","msg":"trace[231529132] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:623; }","duration":"223.432974ms","start":"2025-09-12T22:59:39.822582Z","end":"2025-09-12T22:59:40.046015Z","steps":["trace[231529132] 'agreement among raft nodes before linearized reading' (duration: 223.293661ms)"],"step_count":1} Sep 12 22:59:40.048447 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045694Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:36.511200Z","time spent":"3.534483895s","remote":"10.0.0.71:55982","response type":"/etcdserverpb.KV/Range","request count":0,"request size":82,"response count":8,"response size":31,"request content":"key:\"/registry/prioritylevelconfigurations/\" range_end:\"/registry/prioritylevelconfigurations0\" count_only:true "} Sep 12 22:59:40.048588 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.045809Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:35.969053Z","time spent":"4.076743926s","remote":"10.0.0.71:55614","response type":"/etcdserverpb.KV/Range","request count":0,"request size":72,"response count":1,"response size":841,"request content":"key:\"/registry/events/kube-system/kube-scheduler-localhost.1864ab1f059d5f4f\" "} Sep 12 22:59:40.263602 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.263127Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"155.768119ms","expected-duration":"100ms","prefix":"","request":"header: lease_revoke:","response":"size:29"} Sep 12 22:59:40.263602 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.263315Z","caller":"traceutil/trace.go:171","msg":"trace[1879198345] linearizableReadLoop","detail":"{readStateIndex:651; appliedIndex:650; }","duration":"215.259998ms","start":"2025-09-12T22:59:40.048023Z","end":"2025-09-12T22:59:40.263283Z","steps":["trace[1879198345] 'read index received' (duration: 59.315044ms)","trace[1879198345] 'applied index is now lower than readState.Index' (duration: 155.94312ms)"],"step_count":2} Sep 12 22:59:40.263602 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.263376Z","caller":"traceutil/trace.go:171","msg":"trace[1306881712] transaction","detail":"{read_only:false; response_revision:624; number_of_response:1; }","duration":"214.904406ms","start":"2025-09-12T22:59:40.048467Z","end":"2025-09-12T22:59:40.263371Z","steps":["trace[1306881712] 'process raft request' (duration: 214.767328ms)"],"step_count":1} Sep 12 22:59:40.263850 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.263354Z","caller":"traceutil/trace.go:171","msg":"trace[1701901413] transaction","detail":"{read_only:false; response_revision:625; number_of_response:1; }","duration":"155.435483ms","start":"2025-09-12T22:59:40.107911Z","end":"2025-09-12T22:59:40.263346Z","steps":["trace[1701901413] 'process raft request' (duration: 155.405667ms)"],"step_count":1} Sep 12 22:59:40.263850 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.263535Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"211.011933ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:5"} Sep 12 22:59:40.263850 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.263569Z","caller":"traceutil/trace.go:171","msg":"trace[192845979] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:625; }","duration":"211.061385ms","start":"2025-09-12T22:59:40.052499Z","end":"2025-09-12T22:59:40.263561Z","steps":["trace[192845979] 'agreement among raft nodes before linearized reading' (duration: 211.009698ms)"],"step_count":1} Sep 12 22:59:40.263850 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.263657Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"215.633002ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/masterleases/\" range_end:\"/registry/masterleases0\" ","response":"range_response_count:1 size:125"} Sep 12 22:59:40.263994 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.263813Z","caller":"traceutil/trace.go:171","msg":"trace[1914224506] range","detail":"{range_begin:/registry/masterleases/; range_end:/registry/masterleases0; response_count:1; response_revision:625; }","duration":"215.825766ms","start":"2025-09-12T22:59:40.047979Z","end":"2025-09-12T22:59:40.263805Z","steps":["trace[1914224506] 'agreement among raft nodes before linearized reading' (duration: 215.451641ms)"],"step_count":1} Sep 12 22:59:40.561955 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.561277Z","caller":"traceutil/trace.go:171","msg":"trace[1468667514] transaction","detail":"{read_only:false; response_revision:626; number_of_response:1; }","duration":"292.639258ms","start":"2025-09-12T22:59:40.268603Z","end":"2025-09-12T22:59:40.561242Z","steps":["trace[1468667514] 'process raft request' (duration: 276.288068ms)","trace[1468667514] 'compare' (duration: 16.187081ms)"],"step_count":2} Sep 12 22:59:40.561955 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.561308Z","caller":"traceutil/trace.go:171","msg":"trace[13640310] transaction","detail":"{read_only:false; response_revision:628; number_of_response:1; }","duration":"292.484566ms","start":"2025-09-12T22:59:40.268804Z","end":"2025-09-12T22:59:40.561288Z","steps":["trace[13640310] 'process raft request' (duration: 292.458246ms)"],"step_count":1} Sep 12 22:59:40.561955 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.561330Z","caller":"traceutil/trace.go:171","msg":"trace[1875725776] linearizableReadLoop","detail":"{readStateIndex:654; appliedIndex:653; }","duration":"292.674745ms","start":"2025-09-12T22:59:40.268642Z","end":"2025-09-12T22:59:40.561317Z","steps":["trace[1875725776] 'read index received' (duration: 276.212615ms)","trace[1875725776] 'applied index is now lower than readState.Index' (duration: 16.460687ms)"],"step_count":2} Sep 12 22:59:40.561955 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.561377Z","caller":"traceutil/trace.go:171","msg":"trace[1393309034] transaction","detail":"{read_only:false; response_revision:627; number_of_response:1; }","duration":"292.585386ms","start":"2025-09-12T22:59:40.268769Z","end":"2025-09-12T22:59:40.561354Z","steps":["trace[1393309034] 'process raft request' (duration: 292.450332ms)"],"step_count":1} Sep 12 22:59:40.561955 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.561437Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"292.779773ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/endpointslices/default/kubernetes\" ","response":"range_response_count:1 size:471"} Sep 12 22:59:40.562223 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:40.561474Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"290.627123ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/serviceaccounts/kube-system/persistent-volume-binder\" ","response":"range_response_count:1 size:214"} Sep 12 22:59:40.562223 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.561488Z","caller":"traceutil/trace.go:171","msg":"trace[1586359884] range","detail":"{range_begin:/registry/endpointslices/default/kubernetes; range_end:; response_count:1; response_revision:628; }","duration":"292.875354ms","start":"2025-09-12T22:59:40.268606Z","end":"2025-09-12T22:59:40.561482Z","steps":["trace[1586359884] 'agreement among raft nodes before linearized reading' (duration: 292.744898ms)"],"step_count":1} Sep 12 22:59:40.562223 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:40.561492Z","caller":"traceutil/trace.go:171","msg":"trace[1744202013] range","detail":"{range_begin:/registry/serviceaccounts/kube-system/persistent-volume-binder; range_end:; response_count:1; response_revision:628; }","duration":"290.662389ms","start":"2025-09-12T22:59:40.270823Z","end":"2025-09-12T22:59:40.561485Z","steps":["trace[1744202013] 'agreement among raft nodes before linearized reading' (duration: 290.629998ms)"],"step_count":1} Sep 12 22:59:46.279402 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:46.278938Z","caller":"traceutil/trace.go:171","msg":"trace[40182297] transaction","detail":"{read_only:false; response_revision:645; number_of_response:1; }","duration":"135.131658ms","start":"2025-09-12T22:59:46.143789Z","end":"2025-09-12T22:59:46.278921Z","steps":["trace[40182297] 'process raft request' (duration: 135.032958ms)"],"step_count":1} Sep 12 22:59:57.356642 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:57.355936Z","caller":"traceutil/trace.go:171","msg":"trace[1638406375] transaction","detail":"{read_only:false; response_revision:675; number_of_response:1; }","duration":"387.783118ms","start":"2025-09-12T22:59:56.968131Z","end":"2025-09-12T22:59:57.355914Z","steps":["trace[1638406375] 'process raft request' (duration: 387.670572ms)"],"step_count":1} Sep 12 22:59:57.356642 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:57.356070Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:56.968110Z","time spent":"387.901706ms","remote":"10.0.0.71:55614","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":803,"response count":0,"response size":40,"request content":"compare: success:> failure:<>"} Sep 12 22:59:57.685087 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:57.684619Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"118.884244ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/csistoragecapacities/\" range_end:\"/registry/csistoragecapacities0\" count_only:true ","response":"range_response_count:0 size:5"} Sep 12 22:59:57.685087 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:57.684684Z","caller":"traceutil/trace.go:171","msg":"trace[2116664405] range","detail":"{range_begin:/registry/csistoragecapacities/; range_end:/registry/csistoragecapacities0; response_count:0; response_revision:675; }","duration":"118.995478ms","start":"2025-09-12T22:59:57.565673Z","end":"2025-09-12T22:59:57.684669Z","steps":["trace[2116664405] 'count revisions from in-memory index tree' (duration: 118.835891ms)"],"step_count":1} Sep 12 22:59:58.311896 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.311482Z","caller":"etcdserver/v3_server.go:920","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":7587889447963581100,"retry-timeout":"500ms"} Sep 12 22:59:58.476341 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:58.475897Z","caller":"traceutil/trace.go:171","msg":"trace[1025538345] transaction","detail":"{read_only:false; response_revision:676; number_of_response:1; }","duration":"762.477404ms","start":"2025-09-12T22:59:57.713402Z","end":"2025-09-12T22:59:58.475880Z","steps":["trace[1025538345] 'process raft request' (duration: 762.363596ms)"],"step_count":1} Sep 12 22:59:58.476341 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.476017Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:57.713383Z","time spent":"762.576875ms","remote":"10.0.0.71:55718","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":4229,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:58.974056 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.973725Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"352.011557ms","expected-duration":"100ms","prefix":"","request":"header: txn: success:> failure:<>>","response":"size:16"} Sep 12 22:59:58.974700 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:58.973908Z","caller":"traceutil/trace.go:171","msg":"trace[942543533] linearizableReadLoop","detail":"{readStateIndex:709; appliedIndex:706; }","duration":"1.162789427s","start":"2025-09-12T22:59:57.811103Z","end":"2025-09-12T22:59:58.973893Z","steps":["trace[942543533] 'read index received' (duration: 664.66644ms)","trace[942543533] 'applied index is now lower than readState.Index' (duration: 498.122356ms)"],"step_count":2} Sep 12 22:59:58.974700 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:58.973950Z","caller":"traceutil/trace.go:171","msg":"trace[1473187836] transaction","detail":"{read_only:false; response_revision:678; number_of_response:1; }","duration":"949.202223ms","start":"2025-09-12T22:59:58.024735Z","end":"2025-09-12T22:59:58.973937Z","steps":["trace[1473187836] 'process raft request' (duration: 949.083165ms)"],"step_count":1} Sep 12 22:59:58.974700 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:58.973985Z","caller":"traceutil/trace.go:171","msg":"trace[2061341453] transaction","detail":"{read_only:false; response_revision:679; number_of_response:1; }","duration":"599.925553ms","start":"2025-09-12T22:59:58.374052Z","end":"2025-09-12T22:59:58.973978Z","steps":["trace[2061341453] 'process raft request' (duration: 599.812767ms)"],"step_count":1} Sep 12 22:59:58.974700 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.974051Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:58.374031Z","time spent":"599.977753ms","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":465,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:58.974858 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.974111Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:58.024720Z","time spent":"949.363221ms","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":491,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 22:59:58.974858 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.974122Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"1.163016483s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:5"} Sep 12 22:59:58.974858 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:58.974145Z","caller":"traceutil/trace.go:171","msg":"trace[8697230] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:679; }","duration":"1.163064706s","start":"2025-09-12T22:59:57.811072Z","end":"2025-09-12T22:59:58.974137Z","steps":["trace[8697230] 'agreement among raft nodes before linearized reading' (duration: 1.163032734s)"],"step_count":1} Sep 12 22:59:58.974858 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.974201Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:57.811055Z","time spent":"1.16310849s","remote":"10.0.0.71:55514","response type":"/etcdserverpb.KV/Range","request count":0,"request size":18,"response count":0,"response size":29,"request content":"key:\"/registry/health\" "} Sep 12 22:59:58.974963 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:58.974249Z","caller":"traceutil/trace.go:171","msg":"trace[1544826329] transaction","detail":"{read_only:false; response_revision:677; number_of_response:1; }","duration":"1.005883433s","start":"2025-09-12T22:59:57.968277Z","end":"2025-09-12T22:59:58.974161Z","steps":["trace[1544826329] 'process raft request' (duration: 653.382076ms)","trace[1544826329] 'compare' (duration: 351.849576ms)"],"step_count":2} Sep 12 22:59:58.974963 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.974333Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"363.041389ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/minions/\" range_end:\"/registry/minions0\" count_only:true ","response":"range_response_count:0 size:7"} Sep 12 22:59:58.974963 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:58.974377Z","caller":"traceutil/trace.go:171","msg":"trace[848423236] range","detail":"{range_begin:/registry/minions/; range_end:/registry/minions0; response_count:0; response_revision:679; }","duration":"363.074152ms","start":"2025-09-12T22:59:58.611281Z","end":"2025-09-12T22:59:58.974355Z","steps":["trace[848423236] 'agreement among raft nodes before linearized reading' (duration: 363.03159ms)"],"step_count":1} Sep 12 22:59:58.974963 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.974396Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:57.968249Z","time spent":"1.006071243s","remote":"10.0.0.71:55614","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":785,"response count":0,"response size":40,"request content":"compare: success:> failure:<>"} Sep 12 22:59:58.975068 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:58.974404Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:58.611231Z","time spent":"363.163704ms","remote":"10.0.0.71:55718","response type":"/etcdserverpb.KV/Range","request count":0,"request size":42,"response count":2,"response size":31,"request content":"key:\"/registry/minions/\" range_end:\"/registry/minions0\" count_only:true "} Sep 12 22:59:59.808172 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:59.807778Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"741.255686ms","expected-duration":"100ms","prefix":"","request":"header: lease_revoke:","response":"size:29"} Sep 12 22:59:59.808172 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:59.807867Z","caller":"traceutil/trace.go:171","msg":"trace[2145571985] linearizableReadLoop","detail":"{readStateIndex:711; appliedIndex:710; }","duration":"832.514182ms","start":"2025-09-12T22:59:58.975339Z","end":"2025-09-12T22:59:59.807853Z","steps":["trace[2145571985] 'read index received' (duration: 91.129668ms)","trace[2145571985] 'applied index is now lower than readState.Index' (duration: 741.383482ms)"],"step_count":2} Sep 12 22:59:59.808746 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:59.807957Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"778.205003ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/validatingwebhookconfigurations/\" range_end:\"/registry/validatingwebhookconfigurations0\" count_only:true ","response":"range_response_count:0 size:5"} Sep 12 22:59:59.808746 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:59.807986Z","caller":"traceutil/trace.go:171","msg":"trace[237034825] range","detail":"{range_begin:/registry/validatingwebhookconfigurations/; range_end:/registry/validatingwebhookconfigurations0; response_count:0; response_revision:679; }","duration":"778.264007ms","start":"2025-09-12T22:59:59.029710Z","end":"2025-09-12T22:59:59.807974Z","steps":["trace[237034825] 'agreement among raft nodes before linearized reading' (duration: 778.216025ms)"],"step_count":1} Sep 12 22:59:59.808746 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:59.808012Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:59.029693Z","time spent":"778.310015ms","remote":"10.0.0.71:56042","response type":"/etcdserverpb.KV/Range","request count":0,"request size":90,"response count":0,"response size":29,"request content":"key:\"/registry/validatingwebhookconfigurations/\" range_end:\"/registry/validatingwebhookconfigurations0\" count_only:true "} Sep 12 22:59:59.808746 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:59.807967Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"832.598174ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:5"} Sep 12 22:59:59.808746 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:59.808077Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"708.350386ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/pods/\" range_end:\"/registry/pods0\" count_only:true ","response":"range_response_count:0 size:7"} Sep 12 22:59:59.808916 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:59.808131Z","caller":"traceutil/trace.go:171","msg":"trace[1497272011] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:679; }","duration":"832.732291ms","start":"2025-09-12T22:59:58.975315Z","end":"2025-09-12T22:59:59.808048Z","steps":["trace[1497272011] 'agreement among raft nodes before linearized reading' (duration: 832.5859ms)"],"step_count":1} Sep 12 22:59:59.808916 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:59.808169Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:58.975304Z","time spent":"832.855949ms","remote":"10.0.0.71:55522","response type":"/etcdserverpb.KV/Range","request count":0,"request size":18,"response count":0,"response size":29,"request content":"key:\"/registry/health\" "} Sep 12 22:59:59.808968 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:59.808637Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"233.133994ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/events/\" range_end:\"/registry/events0\" count_only:true ","response":"range_response_count:0 size:7"} Sep 12 22:59:59.808968 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:59.808672Z","caller":"traceutil/trace.go:171","msg":"trace[666421692] range","detail":"{range_begin:/registry/events/; range_end:/registry/events0; response_count:0; response_revision:679; }","duration":"233.201664ms","start":"2025-09-12T22:59:59.575461Z","end":"2025-09-12T22:59:59.808663Z","steps":["trace[666421692] 'agreement among raft nodes before linearized reading' (duration: 233.097063ms)"],"step_count":1} Sep 12 22:59:59.808968 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T22:59:59.808852Z","caller":"traceutil/trace.go:171","msg":"trace[2088284469] range","detail":"{range_begin:/registry/pods/; range_end:/registry/pods0; response_count:0; response_revision:679; }","duration":"708.455287ms","start":"2025-09-12T22:59:59.099680Z","end":"2025-09-12T22:59:59.808136Z","steps":["trace[2088284469] 'agreement among raft nodes before linearized reading' (duration: 708.311442ms)"],"step_count":1} Sep 12 22:59:59.809102 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T22:59:59.808915Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T22:59:59.099638Z","time spent":"709.266483ms","remote":"10.0.0.71:55730","response type":"/etcdserverpb.KV/Range","request count":0,"request size":36,"response count":12,"response size":31,"request content":"key:\"/registry/pods/\" range_end:\"/registry/pods0\" count_only:true "} Sep 12 23:00:01.023785 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:01.023436Z","caller":"traceutil/trace.go:171","msg":"trace[80398923] transaction","detail":"{read_only:false; response_revision:680; number_of_response:1; }","duration":"868.191277ms","start":"2025-09-12T23:00:00.155228Z","end":"2025-09-12T23:00:01.023419Z","steps":["trace[80398923] 'process raft request' (duration: 868.082668ms)"],"step_count":1} Sep 12 23:00:01.023785 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.023529Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T23:00:00.155204Z","time spent":"868.276108ms","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":524,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 23:00:01.755660 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.755215Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"584.994405ms","expected-duration":"100ms","prefix":"","request":"header: txn: success:> failure: >>","response":"size:16"} Sep 12 23:00:01.756072 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:01.755367Z","caller":"traceutil/trace.go:171","msg":"trace[2142767142] transaction","detail":"{read_only:false; response_revision:682; number_of_response:1; }","duration":"777.417139ms","start":"2025-09-12T23:00:00.977938Z","end":"2025-09-12T23:00:01.755355Z","steps":["trace[2142767142] 'process raft request' (duration: 777.356532ms)"],"step_count":1} Sep 12 23:00:01.756072 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:01.755370Z","caller":"traceutil/trace.go:171","msg":"trace[1166310465] transaction","detail":"{read_only:false; response_revision:681; number_of_response:1; }","duration":"1.136015522s","start":"2025-09-12T23:00:00.619341Z","end":"2025-09-12T23:00:01.755356Z","steps":["trace[1166310465] 'process raft request' (duration: 550.801166ms)","trace[1166310465] 'compare' (duration: 584.890615ms)"],"step_count":2} Sep 12 23:00:01.756072 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.755437Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T23:00:00.619321Z","time spent":"1.136077882s","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":525,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 23:00:01.756233 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.755441Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T23:00:00.977916Z","time spent":"777.482595ms","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":492,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 23:00:01.756233 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:01.755438Z","caller":"traceutil/trace.go:171","msg":"trace[2138009527] linearizableReadLoop","detail":"{readStateIndex:713; appliedIndex:711; }","duration":"946.087793ms","start":"2025-09-12T23:00:00.809297Z","end":"2025-09-12T23:00:01.755384Z","steps":["trace[2138009527] 'read index received' (duration: 213.983501ms)","trace[2138009527] 'applied index is now lower than readState.Index' (duration: 732.103611ms)"],"step_count":2} Sep 12 23:00:01.756233 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:01.755494Z","caller":"traceutil/trace.go:171","msg":"trace[1523510969] transaction","detail":"{read_only:false; response_revision:683; number_of_response:1; }","duration":"777.117294ms","start":"2025-09-12T23:00:00.978371Z","end":"2025-09-12T23:00:01.755488Z","steps":["trace[1523510969] 'process raft request' (duration: 776.955805ms)"],"step_count":1} Sep 12 23:00:01.756366 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.755526Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T23:00:00.978344Z","time spent":"777.16745ms","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":465,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 23:00:01.756366 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.755561Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"946.254013ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:5"} Sep 12 23:00:01.756366 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:01.755607Z","caller":"traceutil/trace.go:171","msg":"trace[1497426635] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:683; }","duration":"946.3318ms","start":"2025-09-12T23:00:00.809269Z","end":"2025-09-12T23:00:01.755601Z","steps":["trace[1497426635] 'agreement among raft nodes before linearized reading' (duration: 946.260544ms)"],"step_count":1} Sep 12 23:00:01.756366 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.755630Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T23:00:00.809258Z","time spent":"946.365246ms","remote":"10.0.0.71:55522","response type":"/etcdserverpb.KV/Range","request count":0,"request size":18,"response count":0,"response size":29,"request content":"key:\"/registry/health\" "} Sep 12 23:00:01.801359 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:01.800990Z","caller":"traceutil/trace.go:171","msg":"trace[1508704472] transaction","detail":"{read_only:false; response_revision:684; number_of_response:1; }","duration":"312.155ms","start":"2025-09-12T23:00:01.488824Z","end":"2025-09-12T23:00:01.800979Z","steps":["trace[1508704472] 'process raft request' (duration: 312.055179ms)"],"step_count":1} Sep 12 23:00:01.801359 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.801093Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"142.814423ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/pods/default/test-pod-1\" ","response":"range_response_count:1 size:2176"} Sep 12 23:00:01.801359 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:01.801124Z","caller":"traceutil/trace.go:171","msg":"trace[1901663874] range","detail":"{range_begin:/registry/pods/default/test-pod-1; range_end:; response_count:1; response_revision:684; }","duration":"142.877496ms","start":"2025-09-12T23:00:01.658239Z","end":"2025-09-12T23:00:01.801116Z","steps":["trace[1901663874] 'agreement among raft nodes before linearized reading' (duration: 142.783956ms)"],"step_count":1} Sep 12 23:00:01.801359 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:01.801107Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T23:00:01.488805Z","time spent":"312.266104ms","remote":"10.0.0.71:55730","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":2161,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 23:00:02.048868 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:02.048221Z","caller":"traceutil/trace.go:171","msg":"trace[275681360] linearizableReadLoop","detail":"{readStateIndex:718; appliedIndex:717; }","duration":"113.475102ms","start":"2025-09-12T23:00:01.934726Z","end":"2025-09-12T23:00:02.048201Z","steps":["trace[275681360] 'read index received' (duration: 38.421065ms)","trace[275681360] 'applied index is now lower than readState.Index' (duration: 75.053335ms)"],"step_count":2} Sep 12 23:00:02.048868 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:02.048279Z","caller":"traceutil/trace.go:171","msg":"trace[1835742063] transaction","detail":"{read_only:false; response_revision:686; number_of_response:1; }","duration":"203.088541ms","start":"2025-09-12T23:00:01.845160Z","end":"2025-09-12T23:00:02.048248Z","steps":["trace[1835742063] 'process raft request' (duration: 128.043212ms)","trace[1835742063] 'compare' (duration: 74.888528ms)"],"step_count":2} Sep 12 23:00:02.048868 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:02.048391Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"113.657282ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/persistentvolumeclaims/default/test-dynamic-volume-claim\" ","response":"range_response_count:1 size:1720"} Sep 12 23:00:02.048868 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:02.048437Z","caller":"traceutil/trace.go:171","msg":"trace[2080803422] range","detail":"{range_begin:/registry/persistentvolumeclaims/default/test-dynamic-volume-claim; range_end:; response_count:1; response_revision:686; }","duration":"113.742044ms","start":"2025-09-12T23:00:01.934685Z","end":"2025-09-12T23:00:02.048427Z","steps":["trace[2080803422] 'agreement among raft nodes before linearized reading' (duration: 113.580404ms)"],"step_count":1} Sep 12 23:00:08.126005 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:08.125077Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"110.034636ms","expected-duration":"100ms","prefix":"","request":"header: txn: success:> failure: >>","response":"size:16"} Sep 12 23:00:08.127074 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:08.126759Z","caller":"traceutil/trace.go:171","msg":"trace[538225426] transaction","detail":"{read_only:false; response_revision:699; number_of_response:1; }","duration":"316.653448ms","start":"2025-09-12T23:00:07.810085Z","end":"2025-09-12T23:00:08.126739Z","steps":["trace[538225426] 'process raft request' (duration: 204.891225ms)","trace[538225426] 'compare' (duration: 109.936668ms)"],"step_count":2} Sep 12 23:00:08.127074 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:08.126831Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T23:00:07.810053Z","time spent":"316.74886ms","remote":"10.0.0.71:55810","response type":"/etcdserverpb.KV/Txn","request count":1,"request size":492,"response count":0,"response size":40,"request content":"compare: success:> failure: >"} Sep 12 23:00:08.133766 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:08.133075Z","caller":"traceutil/trace.go:171","msg":"trace[962205025] linearizableReadLoop","detail":"{readStateIndex:733; appliedIndex:731; }","duration":"313.812084ms","start":"2025-09-12T23:00:07.819241Z","end":"2025-09-12T23:00:08.133053Z","steps":["trace[962205025] 'read index received' (duration: 1.106659ms)","trace[962205025] 'applied index is now lower than readState.Index' (duration: 312.704634ms)"],"step_count":2} Sep 12 23:00:08.133766 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:08.133170Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"313.910362ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:5"} Sep 12 23:00:08.133766 etcd-wrapper[1851]: {"level":"info","ts":"2025-09-12T23:00:08.133215Z","caller":"traceutil/trace.go:171","msg":"trace[485567790] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:699; }","duration":"313.999213ms","start":"2025-09-12T23:00:07.819208Z","end":"2025-09-12T23:00:08.133208Z","steps":["trace[485567790] 'agreement among raft nodes before linearized reading' (duration: 313.923248ms)"],"step_count":1} Sep 12 23:00:08.133766 etcd-wrapper[1851]: {"level":"warn","ts":"2025-09-12T23:00:08.133249Z","caller":"v3rpc/interceptor.go:197","msg":"request stats","start time":"2025-09-12T23:00:07.819192Z","time spent":"314.041664ms","remote":"10.0.0.71:55514","response type":"/etcdserverpb.KV/Range","request count":0,"request size":18,"response count":0,"response size":29,"request content":"key:\"/registry/health\" "}