vm-test-run-pg-upgrade-start-guard
checks.aarch64-linux.ext-pg-upgrade-start-guard
· build #440
· raw
1Machine state will be reset. To keep it, pass --keep-vm-state2start all VLans3start vlan4running vlan (pid 7; ctl /build/vde1.ctl)5(finished: start all VLans, in 0.00 seconds)6Test will time out and terminate in 3600 seconds7run the VM test script8additionally exposed symbols:9 server,10 vlan1,11 start_all, test_script, machines, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, Machine, t, debug12start all VMs13server: starting vm14mke2fs 1.47.3 (8-Jul-2025)15qemu-system-aarch64: Could not access KVM kernel module: No such file or directory16qemu-system-aarch64: failed to initialize kvm: No such file or directory17qemu-system-aarch64: falling back to tcg18server # Disk image does not exist, creating the virtualisation disk image...19server # Formatting '/build/vm-state-server/tmp.OCUU3zSCzg', fmt=raw size=429496729620server # Discarding device blocks: 0/1048576 done21server # Creating filesystem with 1048576 4k blocks and 262144 inodes22server # Filesystem UUID: 25d10e26-82d3-4dfe-92df-b0e31b5810b823server # Superblock backups stored on blocks:24server # 32768, 98304, 163840, 229376, 294912, 819200, 88473625server # 26server # Allocating group tables: 0/32 done27server # Writing inode tables: 0/32 done28server # Creating journal (16384 blocks): done29server # Writing superblocks and filesystem accounting information: 0/32 done30server # 31server # Virtualisation disk image created.32server: QEMU running (pid 9)33(finished: start all VMs, in 0.15 seconds)34server: waiting for unit postgresql.service35server: waiting for the VM to finish booting36server # [ 0.000000] Booting Linux on physical CPU 0x0000000000 [0x000f0510]37server # [ 0.000000] Linux version 6.12.63 (nixbld@localhost) (gcc (GCC) 15.2.0, GNU ld (GNU Binutils) 2.44) #1-NixOS SMP Thu Dec 18 12:55:23 UTC 202538server # [ 0.000000] KASLR enabled39server # [ 0.000000] random: crng init done40server # [ 0.000000] Machine model: linux,dummy-virt41server # [ 0.000000] efi: UEFI not found.42server # [ 0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT43server # [ 0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000bfffffff]44server # [ 0.000000] NODE_DATA(0) allocated [mem 0xbfa04780-0xbfa07ebf]45server # [ 0.000000] Zone ranges:46server # [ 0.000000] DMA [mem 0x0000000040000000-0x00000000bfffffff]47server # [ 0.000000] DMA32 empty48server # [ 0.000000] Normal empty49server # [ 0.000000] Device empty50server # [ 0.000000] Movable zone start for each node51server # [ 0.000000] Early memory node ranges52server # [ 0.000000] node 0: [mem 0x0000000040000000-0x00000000bfffffff]53server # [ 0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000bfffffff]54server # [ 0.000000] cma: Reserved 32 MiB at 0x00000000bb800000 on node -155server # [ 0.000000] psci: probing for conduit method from DT.56server # [ 0.000000] psci: PSCIv1.1 detected in firmware.57server # [ 0.000000] psci: Using standard PSCI v0.2 function IDs58server # [ 0.000000] psci: Trusted OS migration not required59server # [ 0.000000] psci: SMC Calling Convention v1.060server # [ 0.000000] percpu: Embedded 88 pages/cpu s180056 r65536 d114856 u36044861server # [ 0.000000] Detected PIPT I-cache on CPU062server # [ 0.000000] CPU features: detected: Address authentication (IMP DEF algorithm)63server # [ 0.000000] CPU features: detected: GIC system register CPU interface64server # [ 0.000000] CPU features: detected: HCRX_EL2 register65server # [ 0.000000] CPU features: detected: 52-bit Virtual Addressing (LPA2)66server # [ 0.000000] CPU features: detected: Spectre-v467server # [ 0.000000] alternatives: applying boot alternatives68server # [ 0.000000] Kernel command line: console=ttyAMA0 console=tty0 panic=1 boot.panic_on_fail clocksource=acpi_pm loglevel=7 net.ifnames=0 lsm=landlock,yama,bpf init=/nix/store/ayraswnmisjhlr7q9kklq7g4d8iw6h3y-nixos-system-server-test/init regInfo=/nix/store/lngr42k8y7svsggv6b428kgbhf6b4mjy-closure-info/registration console=ttyAMA0,115200n8 console=tty069server # [ 0.000000] Unknown kernel command line parameters "regInfo=/nix/store/lngr42k8y7svsggv6b428kgbhf6b4mjy-closure-info/registration", will be passed to user space.70server # [ 0.000000] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)71server # [ 0.000000] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)72server # [ 0.000000] Fallback order for Node 0: 073server # [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 52428874server # [ 0.000000] Policy zone: DMA75server # [ 0.000000] mem auto-init: stack:all(zero), heap alloc:on, heap free:off76server # [ 0.000000] software IO TLB: SWIOTLB bounce buffer size adjusted to 2MB77server # [ 0.000000] software IO TLB: area num 1.78server # [ 0.000000] software IO TLB: mapped [mem 0x00000000bb25a000-0x00000000bb45a000] (2MB)79server # [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=180server # [ 0.000000] allocated 4194304 bytes of page_ext81server # [ 0.000000] ftrace: allocating 72257 entries in 283 pages82server # [ 0.000000] ftrace: allocated 283 pages with 5 groups83server # [ 0.000000] rcu: Hierarchical RCU implementation.84server # [ 0.000000] rcu: RCU event tracing is enabled.85server # [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=1.86server # [ 0.000000] Rude variant of Tasks RCU enabled.87server # [ 0.000000] Tracing variant of Tasks RCU enabled.88server # [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.89server # [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=190server # [ 0.000000] RCU Tasks Rude: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.91server # [ 0.000000] RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.92server # [ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 093server # [ 0.000000] GICv3: 256 SPIs implemented94server # [ 0.000000] GICv3: 0 Extended SPIs implemented95server # [ 0.000000] Root IRQ handler: gic_handle_irq96server # [ 0.000000] GICv3: GICv3 features: 16 PPIs97server # [ 0.000000] GICv3: GICD_CTRL.DS=1, SCR_EL3.FIQ=098server # [ 0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a000099server # [ 0.000000] ITS [mem 0x08080000-0x0809ffff]100server # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Devices @446d0000 (indirect, esz 8, psz 64K, shr 1)101server # [ 0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @446e0000 (flat, esz 8, psz 64K, shr 1)102server # [ 0.000000] GICv3: using LPI property table @0x00000000446f0000103server # [ 0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000044700000104server # [ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.105server # [ 0.000000] arch_timer: cp15 timer(s) running at 1000.00MHz (virt).106server # [ 0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns107server # [ 0.000034] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns108server # [ 0.002583] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)109server # [ 0.014477] Console: colour dummy device 80x25110server # [ 0.016960] printk: legacy console [tty0] enabled111server # [ 0.022285] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000)112server # [ 0.022628] pid_max: default: 32768 minimum: 301113server # [ 0.024227] LSM: initializing lsm=capability,landlock,yama,bpf114server # [ 0.025059] landlock: Up and running.115server # [ 0.025091] Yama: becoming mindful.116server # [ 0.026172] LSM support for eBPF active117server # [ 0.029547] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)118server # [ 0.029756] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)119server # [ 0.056517] cacheinfo: Unable to detect cache hierarchy for CPU 0120server # [ 0.067444] rcu: Hierarchical SRCU implementation.121server # [ 0.067536] rcu: Max phase no-delay instances is 1000.122server # [ 0.076575] fsl-mc MSI: its@8080000 domain created123server # [ 0.079287] EFI services will not be available.124server # [ 0.080415] smp: Bringing up secondary CPUs ...125server # [ 0.080950] smp: Brought up 1 node, 1 CPU126server # [ 0.080985] SMP: Total of 1 processors activated.127server # [ 0.081021] CPU: All CPU(s) started at EL1128server # [ 0.081400] CPU features: detected: Branch Target Identification129server # [ 0.081510] CPU features: detected: 32-bit EL0 Support130server # [ 0.081544] CPU features: detected: 32-bit EL1 Support131server # [ 0.081573] CPU features: detected: ARMv8.4 Translation Table Level132server # [ 0.081609] CPU features: detected: Instruction cache invalidation not required for I/D coherence133server # [ 0.081651] CPU features: detected: Data cache clean to the PoU not required for I/D coherence134server # [ 0.081712] CPU features: detected: Common not Private translations135server # [ 0.081736] CPU features: detected: CRC32 instructions136server # [ 0.081757] CPU features: detected: Data cache clean to Point of Deep Persistence137server # [ 0.081783] CPU features: detected: Data cache clean to Point of Persistence138server # [ 0.081807] CPU features: detected: Data independent timing control (DIT)139server # [ 0.081832] CPU features: detected: E0PD140server # [ 0.081853] CPU features: detected: Enhanced Counter Virtualization141server # [ 0.081876] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF)142server # [ 0.081899] CPU features: detected: Enhanced Privileged Access Never143server # [ 0.081921] CPU features: detected: Enhanced Virtualization Traps144server # [ 0.081944] CPU features: detected: Fine Grained Traps145server # [ 0.082020] CPU features: detected: Generic authentication (IMP DEF algorithm)146server # [ 0.082096] CPU features: detected: RCpc load-acquire (LDAPR)147server # [ 0.082139] CPU features: detected: 52-bit Virtual Addressing for KVM (LPA2)148server # [ 0.082162] CPU features: detected: LSE atomic instructions149server # [ 0.082181] CPU features: detected: Memory Copy and Memory Set instructions150server # [ 0.082201] CPU features: detected: Privileged Access Never151server # [ 0.082220] CPU features: detected: RAS Extension Support152server # [ 0.082238] CPU features: detected: Random Number Generator153server # [ 0.082256] CPU features: detected: Speculation barrier (SB)154server # [ 0.082274] CPU features: detected: Stage-2 Force Write-Back155server # [ 0.082293] CPU features: detected: Trap EL0 IMPLEMENTATION DEFINED functionality156server # [ 0.082316] CPU features: detected: TLB range maintenance instructions157server # [ 0.082336] CPU features: detected: WFx with timeout158server # [ 0.082369] CPU features: detected: Speculative Store Bypassing Safe (SSBS)159server # [ 0.082390] CPU features: detected: Scalable Vector Extension160server # [ 0.085774] alternatives: applying system-wide alternatives161server # [ 0.103526] CPU features: detected: Hardware dirty bit management on CPU0162server # [ 0.104082] SVE: maximum available vector length 256 bytes per vector163server # [ 0.104169] SVE: default vector length 64 bytes per vector164server # [ 0.114681] Memory: 1935308K/2097152K available (23296K kernel code, 6546K rwdata, 24596K rodata, 4416K init, 1047K bss, 118632K reserved, 32768K cma-reserved)165server # [ 0.136241] devtmpfs: initialized166server # [ 0.158645] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns167server # [ 0.159070] futex hash table entries: 256 (order: 2, 16384 bytes, linear)168server # [ 0.160966] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL169server # [ 0.161013] 0 pages in range for non-PLT usage170server # [ 0.161045] 509248 pages in range for PLT usage171server # [ 0.164122] pinctrl core: initialized pinctrl subsystem172server # [ 0.173103] DMI not present or invalid.173server # [ 0.187769] NET: Registered PF_NETLINK/PF_ROUTE protocol family174server # [ 0.200020] DMA: preallocated 256 KiB GFP_KERNEL pool for atomic allocations175server # [ 0.202820] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations176server # [ 0.204935] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations177server # [ 0.205162] audit: initializing netlink subsys (disabled)178server # [ 0.210304] audit: type=2000 audit(0.132:1): state=initialized audit_enabled=0 res=1179server # [ 0.212769] thermal_sys: Registered thermal governor 'fair_share'180server # [ 0.212817] thermal_sys: Registered thermal governor 'bang_bang'181server # [ 0.212866] thermal_sys: Registered thermal governor 'step_wise'182server # [ 0.212897] thermal_sys: Registered thermal governor 'user_space'183server # [ 0.212925] thermal_sys: Registered thermal governor 'power_allocator'184server # [ 0.213480] cpuidle: using governor ladder185server # [ 0.213682] cpuidle: using governor menu186server # [ 0.217969] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.187server # [ 0.218304] ASID allocator initialised with 65536 entries188server # [ 0.224431] Serial: AMBA PL011 UART driver189server # [ 0.269414] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 13, base_baud = 0) is a PL011 rev1190server # [ 0.270666] printk: legacy console [ttyAMA0] enabled191server # [ 0.308348] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages192server # [ 0.308645] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page193server # [ 0.308887] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages194server # [ 0.309103] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page195server # [ 0.310034] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages196server # [ 0.310374] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page197server # [ 0.310471] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages198server # [ 0.310568] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page199server # [ 0.343683] fbcon: Taking over console200server # [ 0.344560] ACPI: Interpreter disabled.201server # [ 0.356121] iommu: Default domain type: Translated202server # [ 0.356288] iommu: DMA domain TLB invalidation policy: strict mode203server # [ 0.359914] SCSI subsystem initialized204server # [ 0.365049] usbcore: registered new interface driver usbfs205server # [ 0.365656] usbcore: registered new interface driver hub206server # [ 0.365904] usbcore: registered new device driver usb207server # [ 0.372729] pps_core: LinuxPPS API ver. 1 registered208server # [ 0.372878] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>209server # [ 0.373653] PTP clock support registered210server # [ 0.374112] EDAC MC: Ver: 3.0.0211server # [ 0.381099] scmi_core: SCMI protocol bus registered212server # [ 0.383450] FPGA manager framework213server # [ 0.384500] Advanced Linux Sound Architecture Driver Initialized.214server # [ 0.400768] vgaarb: loaded215server # [ 0.410689] clocksource: Switched to clocksource arch_sys_counter216server # [ 0.414569] VFS: Disk quotas dquot_6.6.0217server # [ 0.414836] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)218server # [ 0.416624] netfs: FS-Cache loaded219server # [ 0.422918] pnp: PnP ACPI: disabled220server # [ 0.465119] NET: Registered PF_INET protocol family221server # [ 0.466544] IP idents hash table entries: 32768 (order: 6, 262144 bytes, linear)222server # [ 0.575806] tcp_listen_portaddr_hash hash table entries: 1024 (order: 2, 16384 bytes, linear)223server # [ 0.576860] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)224server # [ 0.577998] TCP established hash table entries: 16384 (order: 5, 131072 bytes, linear)225server # [ 0.578506] TCP bind hash table entries: 16384 (order: 7, 524288 bytes, linear)226server # [ 0.578985] TCP: Hash tables configured (established 16384 bind 16384)227server # [ 0.580143] MPTCP token hash table entries: 2048 (order: 4, 49152 bytes, linear)228server # [ 0.580524] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear)229server # [ 0.580785] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear)230server # [ 0.582192] NET: Registered PF_UNIX/PF_LOCAL protocol family231server # [ 0.582637] NET: Registered PF_XDP protocol family232server # [ 0.582871] PCI: CLS 0 bytes, default 64233server # [ 0.585601] Trying to unpack rootfs image as initramfs...234server # [ 0.592447] kvm [1]: HYP mode not available235server # [ 0.769736] Initialise system trusted keyrings236server # [ 0.775038] workingset: timestamp_bits=42 max_order=19 bucket_order=0237server # [ 0.778058] squashfs: version 4.0 (2009/01/31) Phillip Lougher238server # [ 0.785116] 9p: Installing v9fs 9p2000 file system support239server # [ 0.894814] Key type asymmetric registered240server # [ 0.895032] Asymmetric key parser 'x509' registered241server # [ 0.895530] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 244)242server # [ 0.897055] io scheduler mq-deadline registered243server # [ 0.897233] io scheduler kyber registered244server # [ 0.938532] pl061_gpio 9030000.pl061: PL061 GPIO chip registered245server # [ 0.947204] ledtrig-cpu: registered to indicate activity on CPUs246server # [ 0.950731] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:247server # [ 0.951243] pci-host-generic 4010000000.pcie: IO 0x003eff0000..0x003effffff -> 0x0000000000248server # [ 0.951658] pci-host-generic 4010000000.pcie: MEM 0x0010000000..0x003efeffff -> 0x0010000000249server # [ 0.951860] pci-host-generic 4010000000.pcie: MEM 0x8000000000..0xffffffffff -> 0x8000000000250server # [ 0.963384] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits251server # [ 0.964075] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]252server # [ 0.965614] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00253server # [ 0.965955] pci_bus 0000:00: root bus resource [bus 00-ff]254server # [ 0.966164] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]255server # [ 0.966294] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]256server # [ 0.966413] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]257server # [ 0.967577] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint258server # [ 0.970674] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint259server # [ 0.970978] pci 0000:00:01.0: BAR 0 [io 0x0000-0x001f]260server # [ 0.971166] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff]261server # [ 0.971302] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]262server # [ 0.971679] pci 0000:00:01.0: ROM [mem 0x00000000-0x0003ffff pref]263server # [ 0.978723] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint264server # [ 0.978929] pci 0000:00:02.0: BAR 0 [io 0x0000-0x001f]265server # [ 0.979024] pci 0000:00:02.0: BAR 1 [mem 0x00000000-0x00000fff]266server # [ 0.979155] pci 0000:00:02.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]267server # [ 0.979985] pci 0000:00:03.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint268server # [ 0.980707] pci 0000:00:03.0: BAR 0 [io 0x0000-0x003f]269server # [ 0.980824] pci 0000:00:03.0: BAR 1 [mem 0x00000000-0x00000fff]270server # [ 0.980938] pci 0000:00:03.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]271server # [ 0.981615] pci 0000:00:04.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint272server # [ 0.981794] pci 0000:00:04.0: BAR 0 [io 0x0000-0x001f]273server # [ 0.981886] pci 0000:00:04.0: BAR 1 [mem 0x00000000-0x00000fff]274server # [ 0.981986] pci 0000:00:04.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]275server # [ 0.982395] pci 0000:00:05.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint276server # [ 0.982994] pci 0000:00:05.0: BAR 0 [io 0x0000-0x001f]277server # [ 0.983085] pci 0000:00:05.0: BAR 1 [mem 0x00000000-0x00000fff]278server # [ 0.983180] pci 0000:00:05.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]279server # [ 0.983598] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint280server # [ 0.983878] pci 0000:00:06.0: BAR 0 [io 0x0000-0x007f]281server # [ 0.983965] pci 0000:00:06.0: BAR 1 [mem 0x00000000-0x00000fff]282server # [ 0.984343] pci 0000:00:06.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]283server # [ 0.989078] pci 0000:00:07.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint284server # [ 0.989335] pci 0000:00:07.0: BAR 0 [io 0x0000-0x001f]285server # [ 0.989427] pci 0000:00:07.0: BAR 1 [mem 0x00000000-0x00000fff]286server # [ 0.989531] pci 0000:00:07.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]287server # [ 0.989633] pci 0000:00:07.0: ROM [mem 0x00000000-0x0003ffff pref]288server # [ 0.990104] pci 0000:00:08.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint289server # [ 0.990237] pci 0000:00:08.0: BAR 1 [mem 0x00000000-0x00000fff]290server # [ 0.990340] pci 0000:00:08.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]291server # [ 0.990720] pci 0000:00:09.0: [1af4:1050] type 00 class 0x038000 conventional PCI endpoint292server # [ 0.990853] pci 0000:00:09.0: BAR 1 [mem 0x00000000-0x00000fff]293server # [ 0.990955] pci 0000:00:09.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]294server # [ 0.991427] pci 0000:00:0a.0: [8086:24cd] type 00 class 0x0c0320 conventional PCI endpoint295server # [ 0.991555] pci 0000:00:0a.0: BAR 0 [mem 0x00000000-0x00000fff]296server # [ 0.997386] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint297server # [ 0.997927] pci 0000:00:0b.0: BAR 0 [io 0x0000-0x003f]298server # [ 0.998028] pci 0000:00:0b.0: BAR 1 [mem 0x00000000-0x00000fff]299server # [ 0.998495] pci 0000:00:0b.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]300server # [ 0.999035] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint301server # [ 0.999197] pci 0000:00:0c.0: BAR 0 [io 0x0000-0x001f]302server # [ 0.999290] pci 0000:00:0c.0: BAR 1 [mem 0x00000000-0x00000fff]303server # [ 0.999396] pci 0000:00:0c.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]304server # [ 1.005378] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned305server # [ 1.005628] pci 0000:00:07.0: ROM [mem 0x10040000-0x1007ffff pref]: assigned306server # [ 1.005793] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned307server # [ 1.006111] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned308server # [ 1.006411] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned309server # [ 1.007089] pci 0000:00:04.0: BAR 4 [mem 0x800000c000-0x800000ffff 64bit pref]: assigned310server # [ 1.007554] pci 0000:00:05.0: BAR 4 [mem 0x8000010000-0x8000013fff 64bit pref]: assigned311server # [ 1.007742] pci 0000:00:06.0: BAR 4 [mem 0x8000014000-0x8000017fff 64bit pref]: assigned312server # [ 1.007875] pci 0000:00:07.0: BAR 4 [mem 0x8000018000-0x800001bfff 64bit pref]: assigned313server # [ 1.008415] pci 0000:00:08.0: BAR 4 [mem 0x800001c000-0x800001ffff 64bit pref]: assigned314server # [ 1.008637] pci 0000:00:09.0: BAR 4 [mem 0x8000020000-0x8000023fff 64bit pref]: assigned315server # [ 1.008771] pci 0000:00:0b.0: BAR 4 [mem 0x8000024000-0x8000027fff 64bit pref]: assigned316server # [ 1.009157] pci 0000:00:0c.0: BAR 4 [mem 0x8000028000-0x800002bfff 64bit pref]: assigned317server # [ 1.009568] pci 0000:00:01.0: BAR 1 [mem 0x10080000-0x10080fff]: assigned318server # [ 1.009674] pci 0000:00:02.0: BAR 1 [mem 0x10081000-0x10081fff]: assigned319server # [ 1.009768] pci 0000:00:03.0: BAR 1 [mem 0x10082000-0x10082fff]: assigned320server # [ 1.009942] pci 0000:00:04.0: BAR 1 [mem 0x10083000-0x10083fff]: assigned321server # [ 1.010045] pci 0000:00:05.0: BAR 1 [mem 0x10084000-0x10084fff]: assigned322server # [ 1.010138] pci 0000:00:06.0: BAR 1 [mem 0x10085000-0x10085fff]: assigned323server # [ 1.010236] pci 0000:00:07.0: BAR 1 [mem 0x10086000-0x10086fff]: assigned324server # [ 1.010338] pci 0000:00:08.0: BAR 1 [mem 0x10087000-0x10087fff]: assigned325server # [ 1.010432] pci 0000:00:09.0: BAR 1 [mem 0x10088000-0x10088fff]: assigned326server # [ 1.010522] pci 0000:00:0a.0: BAR 0 [mem 0x10089000-0x10089fff]: assigned327server # [ 1.010617] pci 0000:00:0b.0: BAR 1 [mem 0x1008a000-0x1008afff]: assigned328server # [ 1.010710] pci 0000:00:0c.0: BAR 1 [mem 0x1008b000-0x1008bfff]: assigned329server # [ 1.010810] pci 0000:00:06.0: BAR 0 [io 0x1000-0x107f]: assigned330server # [ 1.010915] pci 0000:00:03.0: BAR 0 [io 0x1080-0x10bf]: assigned331server # [ 1.010998] pci 0000:00:0b.0: BAR 0 [io 0x10c0-0x10ff]: assigned332server # [ 1.011084] pci 0000:00:01.0: BAR 0 [io 0x1100-0x111f]: assigned333server # [ 1.011179] pci 0000:00:02.0: BAR 0 [io 0x1120-0x113f]: assigned334server # [ 1.011447] pci 0000:00:04.0: BAR 0 [io 0x1140-0x115f]: assigned335server # [ 1.011581] pci 0000:00:05.0: BAR 0 [io 0x1160-0x117f]: assigned336server # [ 1.011670] pci 0000:00:07.0: BAR 0 [io 0x1180-0x119f]: assigned337server # [ 1.011758] pci 0000:00:0c.0: BAR 0 [io 0x11a0-0x11bf]: assigned338server # [ 1.012783] pci_bus 0000:00: resource 4 [io 0x0000-0xffff]339server # [ 1.013175] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]340server # [ 1.013341] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]341server # [ 1.026288] pci 0000:00:0a.0: enabling device (0000 -> 0002)342server # [ 1.120817] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)343server # [ 1.134046] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)344server # [ 1.135348] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)345server # [ 1.156212] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)346server # [ 1.158201] virtio-pci 0000:00:05.0: enabling device (0000 -> 0003)347server # [ 1.159335] virtio-pci 0000:00:06.0: enabling device (0000 -> 0003)348server # [ 1.161938] virtio-pci 0000:00:07.0: enabling device (0000 -> 0003)349server # [ 1.163277] virtio-pci 0000:00:08.0: enabling device (0000 -> 0002)350server # [ 1.165078] virtio-pci 0000:00:09.0: enabling device (0000 -> 0002)351server # [ 1.167843] virtio-pci 0000:00:0b.0: enabling device (0000 -> 0003)352server # [ 1.169612] virtio-pci 0000:00:0c.0: enabling device (0000 -> 0003)353server # [ 1.200069] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled354server # [ 1.207031] msm_serial: driver initialized355server # [ 1.207714] SuperH (H)SCI(F) driver initialized356server # [ 1.212639] STM32 USART driver initialized357server # [ 1.291079] Freeing initrd memory: 10684K358server # [ 1.294601] loop: module loaded359server # [ 1.295077] virtio_blk virtio5: 1/0/0 default/read/poll queues360server # [ 1.297436] virtio_blk virtio5: [vda] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB)361server # [ 1.309565] megasas: 07.727.03.00-rc1362server # [ 1.314273] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]363server # [ 1.316947] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000364server # [ 1.317489] Intel/Sharp Extended Query Table at 0x0031365server # [ 1.318379] Using buffer write method366server # [ 1.319125] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]367server # [ 1.320947] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000368server # [ 1.321405] Intel/Sharp Extended Query Table at 0x0031369server # [ 1.322280] Using buffer write method370server # [ 1.322902] Concatenating MTD devices:371server # [ 1.322995] (0): "0.flash"372server # [ 1.323053] (1): "0.flash"373server # [ 1.323105] into device "0.flash"374server # [ 1.340604] tun: Universal TUN/TAP device driver, 1.6375server # [ 1.351074] thunder_xcv, ver 1.0376server # [ 1.351284] thunder_bgx, ver 1.0377server # [ 1.351453] nicpf, ver 1.0378server # [ 1.354017] hns3: Hisilicon Ethernet Network Driver for Hip08 Family - version379server # [ 1.354168] hns3: Copyright (c) 2017 Huawei Corporation.380server # [ 1.354483] hclge is initializing381server # [ 1.354809] e1000: Intel(R) PRO/1000 Network Driver382server # [ 1.354891] e1000: Copyright (c) 1999-2006 Intel Corporation.383server # [ 1.355146] e1000e: Intel(R) PRO/1000 Network Driver384server # [ 1.355221] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.385server # [ 1.355409] igb: Intel(R) Gigabit Ethernet Network Driver386server # [ 1.355506] igb: Copyright (c) 2007-2014 Intel Corporation.387server # [ 1.355676] igbvf: Intel(R) Gigabit Virtual Function Network Driver388server # [ 1.355765] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.389server # [ 1.358102] sky2: driver version 1.30390server # [ 1.363815] ehci-pci 0000:00:0a.0: EHCI Host Controller391server # [ 1.364744] ehci-pci 0000:00:0a.0: new USB bus registered, assigned bus number 1392server # [ 1.366890] ehci-pci 0000:00:0a.0: irq 15, io mem 0x10089000393server # [ 1.370309] usbcore: registered new interface driver usb-storage394server # [ 1.370721] usbcore: registered new interface driver usbserial_generic395server # [ 1.371172] usbserial: USB Serial support registered for generic396server # [ 1.377942] ehci-pci 0000:00:0a.0: USB 2.0 started, EHCI 1.00397server # [ 1.381790] rtc-pl031 9010000.pl031: registered as rtc0398server # [ 1.382305] rtc-pl031 9010000.pl031: setting system clock to 2026-10-22T21:29:04 UTC (1792704544)399server # [ 1.383800] i2c_dev: i2c /dev entries driver400server # [ 1.398472] hub 1-0:1.0: USB hub found401server # [ 1.399031] hub 1-0:1.0: 6 ports detected402server # [ 1.404674] sdhci: Secure Digital Host Controller Interface driver403server # [ 1.404859] sdhci: Copyright(c) Pierre Ossman404server # [ 1.406570] Synopsys Designware Multimedia Card Interface Driver405server # [ 1.408041] sdhci-pltfm: SDHCI platform and OF driver helper406server # [ 1.414587] hid: raw HID events driver (C) Jiri Kosina407server # [ 1.417484] usbcore: registered new interface driver usbhid408server # [ 1.417629] usbhid: USB HID core driver409server # [ 1.424724] hw perfevents: enabled with armv8_pmuv3 PMU driver, 7 (0,8000003f) counters available410server # [ 1.437140] drop_monitor: Initializing network drop monitor service411server # [ 1.438372] NET: Registered PF_INET6 protocol family412server # [ 1.448197] Segment Routing with IPv6413server # [ 1.448828] In-situ OAM (IOAM) with IPv6414server # [ 1.450017] NET: Registered PF_PACKET protocol family415server # [ 1.450845] 9pnet: Installing 9P2000 support416server # [ 1.455310] Key type dns_resolver registered417server # [ 1.487449] registered taskstats version 1418server # [ 1.489688] Loading compiled-in X.509 certificates419server # [ 1.540023] Demotion targets for Node 0: null420server # [ 1.541598] Key type .fscrypt registered421server # [ 1.541706] Key type fscrypt-provisioning registered422server # [ 1.548798] input: gpio-keys as /devices/platform/gpio-keys/input/input0423server # [ 1.587438] clk: Disabling unused clocks424server # [ 1.587711] PM: genpd: Disabling unused power domains425server # [ 1.588451] ALSA device list:426server # [ 1.588701] No soundcards found.427server # [ 1.642592] Freeing unused kernel memory: 4416K428server # [ 1.643458] Run /init as init process429server # [ 1.654420] usb 1-1: new high-speed USB device number 2 using ehci-pci430server # [ 1.901317] input: QEMU QEMU USB Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:0a.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input1431server # [ 2.031759] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:0a.0-1/input0432server # [ 2.039081] device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev433server # [ 2.130386] [drm] pci: virtio-gpu-pci detected at 0000:00:09.0434server # [ 2.132017] [drm] features: -virgl +edid -resource_blob -host_visible435server # [ 2.132050] [drm] features: -context_init436server # [ 2.134237] [drm] number of scanouts: 1437server # [ 2.134357] [drm] number of cap sets: 0438server # [ 2.142263] [drm] Initialized virtio_gpu 0.1.0 for 0000:00:09.0 on minor 0439server # [ 2.153050] usb 1-2: new high-speed USB device number 3 using ehci-pci440server # [ 2.172175] Console: switching to colour frame buffer device 160x50441server # [ 2.182386] virtio-pci 0000:00:09.0: [drm] fb0: virtio_gpudrmfb frame buffer device442server # [ 2.405302] input: QEMU QEMU USB Tablet as /devices/platform/4010000000.pcie/pci0000:00/0000:00:0a.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input2443server # [ 2.415138] hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:0a.0-2/input0444server # [ 5.466961] EXT4-fs (vda): mounted filesystem 25d10e26-82d3-4dfe-92df-b0e31b5810b8 r/w with ordered data mode. Quota mode: none.445server # [ 7.412360] EXT4-fs (vda): re-mounted 25d10e26-82d3-4dfe-92df-b0e31b5810b8.446server # [ 7.428818] booting system configuration /nix/store/ayraswnmisjhlr7q9kklq7g4d8iw6h3y-nixos-system-server-test447server # [ 17.385522] systemd[1]: systemd 258.2 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +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 -BTF -XKBCOMMON +UTMP -SYSVINIT +LIBARCHIVE)448server # [ 17.394925] systemd[1]: Detected virtualization qemu.449server # [ 17.399057] systemd[1]: Detected architecture arm64.450server # [ 17.403360] systemd[1]: Detected first boot.451server # [ 17.427383] systemd[1]: Initializing machine ID from random generator.452server # [ 17.453839] systemd[1]: Hostname set to <server>.453server # [ 18.614604] systemd[1]: bpf-restrict-fs: LSM BPF program attached454server # [ 20.273591] systemd[1]: Applying preset policy.455server # [ 23.114457] systemd[1]: Populated /etc with preset unit settings.456server # [ 25.807853] systemd[1]: Queued start job for default target Multi-User System.457server # [ 26.004435] systemd[1]: Created slice Slice /system/getty.458server # [ 26.019429] systemd[1]: Created slice Slice /system/modprobe.459server # [ 26.031730] systemd[1]: Created slice User and Session Slice.460server # [ 26.039732] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.461server # [ 26.045802] systemd[1]: Started Forward Password Requests to Wall Directory Watch.462server # [ 26.051431] systemd[1]: Expecting device /dev/hvc0...463server # [ 26.056689] systemd[1]: Expecting device /dev/ttyAMA0...464server # [ 26.061569] systemd[1]: Expecting device /sys/subsystem/net/devices/eth1...465server # [ 26.066445] systemd[1]: Reached target Local Encrypted Volumes.466server # [ 26.072679] systemd[1]: Reached target Virtual Machines and Containers.467server # [ 26.077404] systemd[1]: Reached target Path Units.468server # [ 26.082543] systemd[1]: Reached target Remote File Systems.469server # [ 26.087563] systemd[1]: Reached target Slice Units.470server # [ 26.092399] systemd[1]: Reached target Swaps.471server # [ 26.128447] systemd[1]: Listening on Process Core Dump Socket.472server # [ 26.152477] systemd[1]: Listening on Credential Encryption/Decryption.473server # [ 26.162569] systemd[1]: Listening on Journal Audit Socket.474server # [ 26.170462] systemd[1]: Listening on Journal Socket (/dev/log).475server # [ 26.177380] systemd[1]: Listening on Journal Sockets.476server # [ 26.186893] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.477server # [ 26.192653] systemd[1]: Make TPM PCR Policy was skipped because of an unmet condition check (ConditionSecurity=measured-uki).478server # [ 26.198339] systemd[1]: Listening on udev Control Socket.479server # [ 26.205278] systemd[1]: Listening on udev Kernel Socket.480server # [ 26.258160] systemd[1]: Mounting Huge Pages File System...481server # [ 26.330093] systemd[1]: Mounting POSIX Message Queue File System...482server # [ 26.441482] systemd[1]: Mounting Kernel Debug File System...483server # [ 26.548605] systemd[1]: Mounting Kernel Trace File System...484server # [ 26.717539] systemd[1]: Starting Create List of Static Device Nodes...485server # [ 26.922632] systemd[1]: Starting Load Kernel Module 9pnet_virtio...486server # [ 26.954582] systemd[1]: Load Kernel Module configfs was skipped because of an unmet condition check (ConditionKernelModuleLoaded=!configfs).487server # [ 27.090675] systemd[1]: Mounting Kernel Configuration File System...488server # [ 27.125568] systemd[1]: Load Kernel Module drm was skipped because of an unmet condition check (ConditionKernelModuleLoaded=!drm).489server # [ 27.143252] systemd[1]: Load Kernel Module efi_pstore was skipped because of an unmet condition check (ConditionKernelModuleLoaded=!efi_pstore).490server # [ 27.273934] systemd[1]: Starting Load Kernel Module fuse...491server # [ 27.287664] systemd[1]: File System Check on Root Device was skipped because of an unmet condition check (ConditionPathIsReadWrite=!/).492server # [ 27.300847] systemd[1]: Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67).493server # [ 27.448277] systemd[1]: Starting Journal Service...494server # [ 27.531190] systemd[1]: Starting Load Kernel Modules...495server # [ 27.622705] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...496server # [ 27.687275] systemd[1]: Starting Remount Root and Kernel File Systems...497server # [ 27.698842] systemd[1]: Early TPM SRK Setup was skipped because of an unmet condition check (ConditionSecurity=measured-uki).498server # [ 27.759834] systemd[1]: Starting Coldplug All udev Devices...499server # [ 27.865154] systemd[1]: Mounted Huge Pages File System.500server # [ 27.878626] systemd[1]: Mounted POSIX Message Queue File System.501server # [ 27.894523] systemd[1]: Mounted Kernel Debug File System.502server # [ 27.907891] systemd[1]: Mounted Kernel Trace File System.503server # [ 27.953331] systemd[1]: Finished Create List of Static Device Nodes.504server # [ 27.967476] systemd[1]: Mounted Kernel Configuration File System.505server # [ 28.054625] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...506server # [ 29.290980] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.507server # [ 29.309825] systemd[1]: Finished Load Kernel Module 9pnet_virtio.508server # [ 29.416434] EXT4-fs (vda): re-mounted 25d10e26-82d3-4dfe-92df-b0e31b5810b8.509server # [ 29.507585] systemd[1]: Finished Load Kernel Modules.510server # [ 29.622692] systemd[1]: Starting Firewall...511server: Guest root shell did not produce any data yet...512server: To debug, enter the VM and run 'systemctl status backdoor.service'.513server # [ 29.707055] systemd[1]: Starting Apply Kernel Variables...514server # [ 29.737762] systemd[1]: Finished Remount Root and Kernel File Systems.515server # [ 29.751403] systemd[1]: Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore).516server # [ 29.840894] systemd[1]: Starting Load/Save OS Random Seed...517server # [ 29.856387] systemd[1]: TPM SRK Setup was skipped because of an unmet condition check (ConditionSecurity=measured-uki).518server # [ 30.299476] fuse: init (API version 7.41)519server # [ 30.431610] systemd[1]: modprobe@fuse.service: Deactivated successfully.520server # [ 30.458233] systemd[1]: Finished Load Kernel Module fuse.521server # [ 30.486090] systemd-journald[376]: Collecting audit messages is enabled.522server # [ 30.530501] systemd[1]: Mounting FUSE Control File System...523server # [ 30.818951] systemd[1]: Mounted FUSE Control File System.524server # [ 31.594037] systemd[1]: Finished Load/Save OS Random Seed.525server # [ 31.610397] systemd[1]: Reached target First Boot Complete.526server # [ 32.075225] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.527server # [ 32.146734] systemd[1]: Starting Create Static Device Nodes in /dev...528server # [ 32.174760] systemd[1]: Finished Apply Kernel Variables.529server # [ 33.191651] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.530server # [ 33.910519] systemd[1]: Finished Create Static Device Nodes in /dev.531server # [ 33.935600] systemd[1]: Reached target Preparation for Local File Systems.532server # [ 34.003361] systemd[1]: Mounting /run/wrappers...533server # [ 34.071487] systemd[1]: Starting Rule-based Manager for Device Events and Files...534server # [ 34.653071] systemd[1]: Mounted /run/wrappers.535server # [ 34.662794] systemd[1]: Reached target Local File Systems.536server # [ 34.706336] systemd[1]: Listening on Boot Entries Service Socket.537server # [ 34.775108] systemd[1]: Starting Create SUID/SGID Wrappers...538server # [ 34.785329] systemd[1]: Update Boot Loader Random Seed was skipped because no trigger condition checks were met.539server # [ 34.840785] systemd[1]: Starting Save Transient machine-id to Disk...540server # [ 35.349873] systemd[1]: Started Journal Service.541server # [ 35.243826] systemd-modules-load[377]: Module 'atkbd' is built in542server # [ 35.335263] systemd-modules-load[377]: Module 'loop' is built in543server # [ 35.446791] systemd-oomd[378]: No swap; memory pressure usage will be degraded544server # [ 35.519990] systemd[1]: Starting Flush Journal to Persistent Storage...545server # [ 36.163058] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.546server # [ 36.218254] systemd[1]: Finished Save Transient machine-id to Disk.547server # [ 36.793778] systemd-journald[376]: Received client request to flush runtime journal.548server # [ 37.491265] systemd-udevd[405]: Using default interface naming scheme 'v258'.549server # [ 37.563687] systemd[1]: Finished Flush Journal to Persistent Storage.550server # [ 37.605742] systemd[1]: Starting Create System Files and Directories...551server # [ 40.670561] systemd[1]: Finished Create System Files and Directories.552server # [ 40.739636] systemd[1]: Starting Rebuild Journal Catalog...553server # [ 40.836174] systemd[1]: Starting Record System Boot/Shutdown in UTMP...554server # [ 41.094408] systemd[1]: Started Rule-based Manager for Device Events and Files.555server # [ 42.173326] systemd[1]: Finished Record System Boot/Shutdown in UTMP.556server # [ 43.859260] systemd[1]: Finished Rebuild Journal Catalog.557server # [ 43.921795] systemd[1]: Starting Update is Completed...558server # [ 45.091764] systemd[1]: Finished Update is Completed.559server # [ 48.662948] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.560server # [ 48.678337] systemd[1]: Finished Create SUID/SGID Wrappers.561server # [ 48.687153] systemd[1]: suid-sgid-wrappers.service: Consumed 1.983s CPU time, 5.5M memory peak.562server # [ 50.948500] systemd[1]: Finished Firewall.563server # [ 54.659877] systemd[1]: Finished Coldplug All udev Devices.564server # [ 54.670475] systemd[1]: Reached target System Initialization.565server # [ 54.686418] systemd[1]: Started Discard unused filesystem blocks once a week.566server # [ 54.698901] systemd[1]: Started Daily Cleanup of Temporary Directories.567server # [ 54.713701] systemd[1]: Reached target Timer Units.568server # [ 54.717327] systemd[1]: Listening on D-Bus System Message Bus Socket.569server # [ 54.721199] systemd[1]: Listening on Nix Daemon Socket.570server # [ 54.722878] systemd[1]: Listening on Hostname Service Socket.571server # [ 54.730580] systemd[1]: Reached target Socket Units.572server # [ 54.757915] systemd[1]: Reached target Basic System.573server # [ 54.770924] systemd[1]: Starting Import lastlog data into lastlog2 database...574server # [ 54.797593] systemd[1]: Starting Name Service Cache Daemon (nsncd)...575server # [ 54.868122] systemd[1]: Starting postgresql.service...576server # [ 54.909356] systemd[1]: Started Reset console on configuration changes.577server # [ 55.025375] systemd[1]: Starting resolvconf update...578server # [ 55.074298] systemd[1]: Starting D-Bus System Message Bus...579server # [ 56.918905] systemd[1]: Finished Import lastlog data into lastlog2 database.580server # [ 57.124119] runuser[621]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)581server # [ 57.400255] systemd[1]: Started Name Service Cache Daemon (nsncd).582server # [ 57.425524] systemd[1]: Reached target Host and Network Name Lookups.583server # [ 57.457645] systemd[1]: Reached target User and Group Name Lookups.584server # [ 57.488528] nsncd[610]: Oct 22 21:30:00.576 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"585server # [ 57.532978] systemd[1]: Starting User Login Management...586server # [ 58.043211] dbus-daemon[614]: dbus[614]: Unknown username "systemd-timesync" in message bus configuration file587server # [ 58.863512] systemd[1]: Started D-Bus System Message Bus.588server: Guest root shell did not produce any data yet...589server: To debug, enter the VM and run 'systemctl status backdoor.service'.590server # [ 59.856990] systemd[1]: Stopped target Host and Network Name Lookups.591server # [ 59.911296] systemd[1]: Stopping Host and Network Name Lookups...592server # [ 59.958158] systemd[1]: Stopped target User and Group Name Lookups.593server # [ 59.975570] systemd[1]: Stopping User and Group Name Lookups...594server # [ 59.986168] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...595server # [ 60.011403] systemd[1]: nscd.service: Deactivated successfully.596server # [ 60.051301] systemd[1]: Stopped Name Service Cache Daemon (nsncd).597server # [ 60.169823] systemd[1]: Starting Name Service Cache Daemon (nsncd)...598server # [ 60.981173] systemd-logind[628]: New seat seat0.599server # [ 61.136277] systemd[1]: Started User Login Management.600server # [ 61.167758] systemd[1]: Starting linger-users.service...601server # [ 61.469607] systemd[1]: Started Name Service Cache Daemon (nsncd).602server # [ 61.485298] systemd[1]: Reached target Host and Network Name Lookups.603server # [ 61.533126] nsncd[674]: Oct 22 21:30:04.711 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"604server # [ 61.552931] systemd[1]: Reached target User and Group Name Lookups.605server # [ 61.656694] init-old[623]: The files belonging to this database system will be owned by user "postgres".606server # [ 61.678464] init-old[623]: This user must also own the server process.607server # [ 61.830427] init-old[623]: The database cluster will be initialized with locale "C".608server # [ 61.843367] init-old[623]: The default text search configuration will be set to "english".609server # [ 61.851513] init-old[623]: Data page checksums are disabled.610server # [ 61.869232] init-old[623]: fixing permissions on existing directory /var/lib/postgresql/data ... ok611server # [ 61.881972] init-old[623]: creating subdirectories ... ok612server # [ 61.903192] init-old[623]: selecting dynamic shared memory implementation ... posix613server # [ 62.068759] systemd[1]: linger-users.service: Deactivated successfully.614server # [ 62.086048] systemd[1]: Finished linger-users.service.615server # [ 62.411861] systemd[1]: Finished resolvconf update.616server # [ 62.450067] systemd[1]: Reached target Preparation for Network.617server # [ 62.495299] systemd[1]: Starting DHCP Client...618server # [ 63.820570] init-old[623]: selecting default max_connections ... 100619server # [ 64.839533] init-old[623]: selecting default shared_buffers ... 128MB620server # [ 65.512029] dhcpcd[711]: dhcpcd-10.2.4 starting621server # [ 65.707615] dhcpcd[729]: dev: loaded udev622server # [ 66.259460] 8021q: 802.1Q VLAN Support v1.8623server # [ 66.935608] cfg80211: Loading compiled-in X.509 certificates for regulatory database624server # [ 67.207824] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'625server # [ 67.218135] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'626server # [ 67.245951] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2627server # [ 67.258049] cfg80211: failed to load regulatory.db628server # [ 68.541251] 8021q: adding VLAN 0 to HW filter on device eth0629server # [ 68.466943] dhcpcd[729]: eth0: waiting for carrier630server # [ 68.485781] dhcpcd[729]: eth0: carrier acquired631server # [ 68.654177] dhcpcd[729]: DUID 00:01:00:01:32:6d:3c:e3:52:54:00:12:34:56632server # [ 68.658354] dhcpcd[729]: eth0: IAID 00:12:34:56633server # [ 68.673785] dhcpcd[729]: eth0: adding address fe80::5054:ff:fe12:3456634server # [ 69.591391] dhcpcd[729]: eth0: soliciting a DHCP lease635server # [ 69.627363] dhcpcd[729]: eth0: offered 10.0.2.15 from 10.0.2.2636server # [ 69.645731] dhcpcd[729]: eth0: probing address 10.0.2.15/24637server # [ 70.206507] dhcpcd[729]: eth0: soliciting an IPv6 router638server # [ 70.224051] dhcpcd[729]: eth0: Router Advertisement from fe80::2639server # [ 70.237940] dhcpcd[729]: eth0: adding address fec0::5054:ff:fe12:3456/64640server # [ 70.247826] dhcpcd[729]: eth0: adding route to fec0::/64641server # [ 70.263451] dhcpcd[729]: eth0: adding default route via fe80::2642server # [ 74.531400] dhcpcd[729]: eth0: leased 10.0.2.15 for 86400 seconds643server # [ 74.553363] dhcpcd[729]: eth0: adding route to 10.0.2.0/24644server # [ 74.574928] dhcpcd[729]: eth0: adding default route via 10.0.2.2645server # [ 76.639039] init-old[623]: selecting default time zone ... UTC646server # [ 76.717927] init-old[623]: creating configuration files ... ok647server # [ 78.179360] systemd[1]: Started DHCP Client.648server # [ 82.708786] init-old[623]: running bootstrap script ... ok649server # [ 84.175939] systemd[1]: Found device /dev/hvc0.650server # [ 86.664373] (udev-worker)[893]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.651server # [ 86.682098] (udev-worker)[893]: Network interface NamePolicy= disabled on kernel command line.652server # [ 86.696491] (udev-worker)[892]: Network interface NamePolicy= disabled on kernel command line.653server # [ 87.540575] systemd[1]: Found device /dev/ttyAMA0.654server # [ 87.592614] systemd[1]: Started backdoor.service.655server # connecting to host...656server: Guest shell says: b'Spawning backdoor root shell...\n'657server: connected to guest root shell658server: (connecting took 89.33 seconds)659server: (finished: waiting for the VM to finish booting, in 89.33 seconds)660server # [ 89.570313] systemd[1]: Found device Virtio network device.661server # [ 89.642628] systemd[1]: Starting Address configuration of eth1...662server # [ 89.663820] dhcpcd[729]: eth0: IAID 00:12:34:56663server # [ 90.149107] dhcpcd[729]: eth0: soliciting an IPv6 router664server # [ 91.404746] 8021q: adding VLAN 0 to HW filter on device eth1665server # [ 91.689379] network-addresses-eth1-start[919]: adding address 192.168.1.1/24... done666server # [ 91.787902] dhcpcd[729]: eth0: rebinding lease of 10.0.2.15667server # [ 91.799507] dhcpcd[729]: eth0: leased 10.0.2.15 for 86400 seconds668server # [ 92.006434] network-addresses-eth1-start[919]: adding address 2001:db8:1::1/64... done669server # [ 92.484119] systemd[1]: Finished Address configuration of eth1.670server # [ 92.557290] systemd[1]: Starting Networking Setup...671server # [ 96.539579] systemd[1]: Finished Networking Setup.672server # [ 96.572053] systemd[1]: Reached target Network.673server # [ 96.606308] systemd[1]: Starting Permit User Sessions...674server # [ 97.182081] systemd[1]: Finished Permit User Sessions.675server # [ 97.237542] systemd[1]: Started Getty on tty1.676server # [ 97.238914] systemd[1]: Reached target Login Prompts.677server # [ 107.164213] init-old[623]: performing post-bootstrap initialization ... ok678server # [ 111.092943] init-old[623]: syncing data to disk ... ok679server # [ 111.099197] init-old[623]: initdb: warning: enabling "trust" authentication for local connections680server # [ 111.099916] init-old[623]: initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.681server # [ 111.111714] init-old[623]: Success. You can now start the database server using:682server # [ 111.119272] init-old[623]: /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/pg_ctl -D /var/lib/postgresql/data -l logfile start683server # [ 111.148020] runuser[621]: pam_unix(runuser:session): session closed for user postgres684server # [ 112.643252] postgres[1100]: 2026-10-22 21:30:55.872 UTC [1100] LOG: starting PostgreSQL 15.19 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 15.2.0, 64-bit685server # [ 112.745721] postgres[1100]: 2026-10-22 21:30:55.981 UTC [1100] LOG: listening on IPv6 address "::1", port 5432686server # [ 112.754507] postgres[1100]: 2026-10-22 21:30:55.986 UTC [1100] LOG: listening on IPv4 address "127.0.0.1", port 5432687server # [ 112.768914] postgres[1100]: 2026-10-22 21:30:56.005 UTC [1100] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"688server # [ 112.915905] postgres[1107]: 2026-10-22 21:30:56.136 UTC [1107] LOG: database system was shut down at 2026-10-22 21:30:50 UTC689server # [ 113.040531] postgres[1100]: 2026-10-22 21:30:56.277 UTC [1100] LOG: database system is ready to accept connections690server # [ 113.131993] systemd[1]: Started postgresql.service.691server # [ 113.139961] systemd[1]: Reached target Multi-User System.692server # [ 113.150421] systemd[1]: Startup finished in 16.759s (kernel) + 1min 36.365s (userspace) = 1min 53.124s.693server: (finished: waiting for unit postgresql.service, in 114.56 seconds)694subtest: Seed the source cluster695server: must succeed: /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/psql -h 127.0.0.1 -p 5432 -U postgres -d postgres -Atc "create table seed as select g as id, repeat(md5(g::text), 20) as pad from generate_series(1, 100000) g"696server # [ 115.403044] systemd-logind[628]: Watching system buttons on /dev/input/event0 (gpio-keys)697server # [ 118.885593] mousedev: PS/2 mouse device common for all mice698server # [ 121.501253] systemd-logind[628]: Watching system buttons on /dev/input/event1 (QEMU QEMU USB Keyboard)699server: (finished: must succeed: /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/psql -h 127.0.0.1 -p 5432 -U postgres -d postgres -Atc "create table seed as select g as id, repeat(md5(g::text), 20) as pad from generate_series(1, 100000) g", in 12.94 seconds)700server: must succeed: /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/psql -h 127.0.0.1 -p 5432 -U postgres -d postgres -Atc "select count(*) || ',' || sum(id) from seed"701server: (finished: must succeed: /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/psql -h 127.0.0.1 -p 5432 -U postgres -d postgres -Atc "select count(*) || ',' || sum(id) from seed", in 2.05 seconds)702(finished: subtest: Seed the source cluster, in 14.99 seconds)703subtest: Control: with no guard the start loop brings the source up704server: must succeed: systemctl stop postgresql705server # [ 129.650224] postgres[1100]: 2026-10-22 21:31:12.850 UTC [1100] LOG: received fast shutdown request706server # [ 129.670114] postgres[1100]: 2026-10-22 21:31:12.885 UTC [1100] LOG: aborting any active transactions707server # [ 129.712524] systemd[1]: Stopping postgresql.service...708server # [ 129.834655] postgres[1100]: 2026-10-22 21:31:13.061 UTC [1100] LOG: background worker "logical replication launcher" (PID 1110) exited with exit code 1709server # [ 129.869744] postgres[1105]: 2026-10-22 21:31:13.084 UTC [1105] LOG: shutting down710server # [ 129.871286] postgres[1105]: 2026-10-22 21:31:13.102 UTC [1105] LOG: checkpoint starting: shutdown immediate711server # [ 130.781070] postgres[1105]: 2026-10-22 21:31:14.017 UTC [1105] LOG: checkpoint complete: wrote 2176 buffers (13.3%); 0 WAL file(s) added, 0 removed, 4 recycled; write=0.509 s, sync=0.286 s, total=0.933 s; sync files=28, longest=0.219 s, average=0.011 s; distance=69073 kB, estimate=69073 kB712server # [ 130.895188] postgres[1100]: 2026-10-22 21:31:14.125 UTC [1100] LOG: database system is shut down713server # [ 130.963000] systemd[1]: postgresql.service: Deactivated successfully.714server # [ 130.989918] systemd[1]: Stopped postgresql.service.715server # [ 130.991147] systemd[1]: postgresql.service: Consumed 21.076s CPU time, 233.2M memory peak, 241.7M written to disk, 1.2K incoming IP traffic, 1.7K outgoing IP traffic.716server: (finished: must succeed: systemctl stop postgresql, in 1.97 seconds)717server: must succeed: systemd-run --unit=salt-sim --collect /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive salt_sim718server # [ 131.713487] systemd[1]: Started [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive salt_sim.719server # Running as unit: salt-sim.service; invocation ID: 6986b92f6bc24a61b4325a5de23abc45720server: (finished: must succeed: systemd-run --unit=salt-sim --collect /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive salt_sim, in 0.82 seconds)721server: waiting for success: systemctl is-active --quiet postgresql722server # [ 132.681914] systemd[1]: Starting postgresql.service...723server # [ 134.171178] postgres[1232]: 2026-10-22 21:31:17.397 UTC [1232] LOG: starting PostgreSQL 15.19 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 15.2.0, 64-bit724server # [ 134.210997] postgres[1232]: 2026-10-22 21:31:17.448 UTC [1232] LOG: listening on IPv6 address "::1", port 5432725server # [ 134.221865] postgres[1232]: 2026-10-22 21:31:17.454 UTC [1232] LOG: listening on IPv4 address "127.0.0.1", port 5432726server # [ 134.235255] postgres[1232]: 2026-10-22 21:31:17.471 UTC [1232] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"727server # [ 134.388084] postgres[1254]: 2026-10-22 21:31:17.620 UTC [1254] LOG: database system was shut down at 2026-10-22 21:31:13 UTC728server # [ 134.603367] postgres[1232]: 2026-10-22 21:31:17.837 UTC [1232] LOG: database system is ready to accept connections729server # [ 134.643141] systemd[1]: Started postgresql.service.730server: (finished: waiting for success: systemctl is-active --quiet postgresql, in 2.98 seconds)731server: must succeed: systemctl stop salt-sim732server # [ 135.734197] systemd[1]: Stopping [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive salt_sim...733server # [ 135.813113] systemd[1]: salt-sim.service: Deactivated successfully.734server # [ 135.826997] systemd[1]: Stopped [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive salt_sim.735server: (finished: must succeed: systemctl stop salt-sim, in 1.08 seconds)736(finished: subtest: Control: with no guard the start loop brings the source up, in 6.84 seconds)737subtest: A systemd start is refused while the block is held738server: must succeed: systemd-run --unit=hold-block --collect /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive hold_block739server # [ 136.541108] systemd[1]: Started [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive hold_block.740server # Running as unit: hold-block.service; invocation ID: 3dd6ab117ae24fc281b8d5ca61476d59741server: (finished: must succeed: systemd-run --unit=hold-block --collect /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive hold_block, in 0.73 seconds)742server: waiting for success: systemctl show -p ExecCondition postgresql | grep -q start-guard743server # [ 137.342531] postgres[1232]: 2026-10-22 21:31:20.542 UTC [1232] LOG: received fast shutdown request744server # [ 137.364222] systemd[1]: Stopping postgresql.service...745server # [ 137.377701] postgres[1232]: 2026-10-22 21:31:20.599 UTC [1232] LOG: aborting any active transactions746server # [ 137.535130] postgres[1232]: 2026-10-22 21:31:20.770 UTC [1232] LOG: background worker "logical replication launcher" (PID 1257) exited with exit code 1747server # [ 137.557985] postgres[1252]: 2026-10-22 21:31:20.779 UTC [1252] LOG: shutting down748server # [ 137.576010] postgres[1252]: 2026-10-22 21:31:20.797 UTC [1252] LOG: checkpoint starting: shutdown immediate749server # [ 137.685157] postgres[1252]: 2026-10-22 21:31:20.916 UTC [1252] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.038 s, sync=0.017 s, total=0.137 s; sync files=2, longest=0.010 s, average=0.009 s; distance=0 kB, estimate=0 kB750server # [ 137.796906] postgres[1232]: 2026-10-22 21:31:21.025 UTC [1232] LOG: database system is shut down751server # [ 137.889020] systemd[1]: postgresql.service: Deactivated successfully.752server # [ 137.908789] systemd[1]: Stopped postgresql.service.753server # [ 138.363338] systemd[1]: Reload requested from client PID 1299 ('systemctl') (unit hold-block.service)...754server # [ 138.379910] systemd[1]: Reloading...755server # [ 144.531643] systemd[1]: Reloading finished in 6141 ms.756server: (finished: waiting for success: systemctl show -p ExecCondition postgresql | grep -q start-guard, in 8.63 seconds)757server: must fail: systemctl start postgresql758server # [ 145.879334] systemd[1]: Starting postgresql.service...759server # [ 146.542697] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION760server # [ 146.572046] systemd[1]: postgresql.service: Failed with result 'exit-code'.761server # Job for postgresql.service failed because the control process exited with error code.762server # See "systemctl status postgresql.service" and "journalctl -xeu postgresql.service" for details.763server # [ 146.582774] systemd[1]: Failed to start postgresql.service.764server: (finished: must fail: systemctl start postgresql, in 1.35 seconds)765server: must succeed: sleep 5766server: (finished: must succeed: sleep 5, in 5.50 seconds)767server: must fail: systemctl is-active --quiet postgresql768server: (finished: must fail: systemctl is-active --quiet postgresql, in 0.48 seconds)769server: must succeed: systemctl show -p Restart postgresql770server: (finished: must succeed: systemctl show -p Restart postgresql, in 0.60 seconds)771(finished: subtest: A systemd start is refused while the block is held, in 17.29 seconds)772subtest: The block expires on its own when the holder is SIGKILLed773server: must succeed: systemctl kill -s KILL hold-block774server # [ 153.781359] systemd[1]: hold-block.service: Sent signal SIGKILL to main process 1270 (sleep) on client request.775server # [ 153.786567] systemd[1]: hold-block.service: Killed unit cgroup '/system.slice/hold-block.service' with SIGKILL on client request.776server # [ 153.787881] systemd[1]: hold-block.service: Main process exited, code=killed, status=9/KILL777server # [ 153.809809] systemd[1]: hold-block.service: Failed with result 'signal'.778server: (finished: must succeed: systemctl kill -s KILL hold-block, in 0.62 seconds)779server: waiting for failure: systemctl is-active --quiet hold-block780server: (finished: waiting for failure: systemctl is-active --quiet hold-block, in 0.69 seconds)781server: must succeed: systemctl start postgresql782server # [ 155.041504] systemd[1]: Starting postgresql.service...783server # [ 157.160925] postgres[1415]: 2026-10-22 21:31:40.384 UTC [1415] LOG: starting PostgreSQL 15.19 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 15.2.0, 64-bit784server # [ 157.191715] postgres[1415]: 2026-10-22 21:31:40.427 UTC [1415] LOG: listening on IPv6 address "::1", port 5432785server # [ 157.198322] postgres[1415]: 2026-10-22 21:31:40.431 UTC [1415] LOG: listening on IPv4 address "127.0.0.1", port 5432786server # [ 157.214049] postgres[1415]: 2026-10-22 21:31:40.448 UTC [1415] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"787server # [ 157.331850] postgres[1420]: 2026-10-22 21:31:40.561 UTC [1420] LOG: database system was shut down at 2026-10-22 21:31:20 UTC788server # [ 157.434251] postgres[1415]: 2026-10-22 21:31:40.671 UTC [1415] LOG: database system is ready to accept connections789server # [ 158.206729] systemd[1]: Reload requested from client PID 1435 ('systemctl') (unit postgresql.service)...790server # [ 158.218233] systemd[1]: Reloading...791server # [ 164.214997] systemd[1]: Reloading finished in 5998 ms.792server # [ 164.589124] systemd[1]: Started postgresql.service.793server: (finished: must succeed: systemctl start postgresql, in 10.19 seconds)794server: waiting for unit postgresql.service795server: (finished: waiting for unit postgresql.service, in 0.97 seconds)796server: must fail: test -e /run/systemd/system/postgresql.service.d/pg-upgrade-lock.conf797server: (finished: must fail: test -e /run/systemd/system/postgresql.service.d/pg-upgrade-lock.conf, in 0.34 seconds)798server: must succeed: systemctl show -p Restart postgresql799server: (finished: must succeed: systemctl show -p Restart postgresql, in 0.60 seconds)800server: must succeed: systemctl show -p NeedDaemonReload postgresql801server: (finished: must succeed: systemctl show -p NeedDaemonReload postgresql, in 0.62 seconds)802(finished: subtest: The block expires on its own when the holder is SIGKILLed, in 14.03 seconds)803subtest: The pid lock stops a direct start once the new cluster is up804server: must succeed: systemctl stop postgresql805server # [ 167.834514] systemd[1]: Stopping postgresql.service...806server # [ 167.859944] postgres[1415]: 2026-10-22 21:31:51.037 UTC [1415] LOG: received fast shutdown request807server # [ 167.883960] postgres[1415]: 2026-10-22 21:31:51.090 UTC [1415] LOG: aborting any active transactions808server # [ 167.996717] postgres[1415]: 2026-10-22 21:31:51.231 UTC [1415] LOG: background worker "logical replication launcher" (PID 1426) exited with exit code 1809server # [ 168.097373] postgres[1417]: 2026-10-22 21:31:51.287 UTC [1417] LOG: shutting down810server # [ 168.099478] postgres[1417]: 2026-10-22 21:31:51.303 UTC [1417] LOG: checkpoint starting: shutdown immediate811server # [ 168.181226] postgres[1417]: 2026-10-22 21:31:51.416 UTC [1417] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.035 s, sync=0.007 s, total=0.129 s; sync files=2, longest=0.004 s, average=0.004 s; distance=0 kB, estimate=0 kB812server # [ 168.241745] postgres[1415]: 2026-10-22 21:31:51.477 UTC [1415] LOG: database system is shut down813server # [ 168.308127] systemd[1]: postgresql.service: Deactivated successfully.814server # [ 168.321236] systemd[1]: Stopped postgresql.service.815server # [ 168.322364] systemd[1]: postgresql.service: Consumed 1.023s CPU time, 18.9M memory peak, 32K written to disk.816server: (finished: must succeed: systemctl stop postgresql, in 1.16 seconds)817server: must succeed: systemd-run --unit=hold-lock --collect /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive hold_lock818server # [ 168.954929] systemd[1]: Started [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive hold_lock.819server # Running as unit: hold-lock.service; invocation ID: b2e6c221f1a34c91a748293525733a6e820server: (finished: must succeed: systemd-run --unit=hold-lock --collect /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive hold_lock, in 0.67 seconds)821server: waiting for success: test -s /var/lib/postgresql/data/postmaster.pid822server # [ 170.023786] runuser[1512]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)823server # [ 171.666146] drive[1513]: [21:31:54] Locked /var/lib/postgresql/data with pg_upgrade pid 1516824server: (finished: waiting for success: test -s /var/lib/postgresql/data/postmaster.pid, in 3.67 seconds)825server: must fail: runuser -u postgres -- /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/pg_ctl start -D /var/lib/postgresql/data -w -s -l /tmp/pg_ctl.log -t 5826server # [ 173.238535] runuser[1550]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)827server # pg_ctl: another server might be running; trying to start server anyway828server # pg_ctl: could not start server829server # Examine the log output.830server # [ 174.591333] runuser[1550]: pam_unix(runuser:session): session closed for user postgres831server: (finished: must fail: runuser -u postgres -- /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/pg_ctl start -D /var/lib/postgresql/data -w -s -l /tmp/pg_ctl.log -t 5, in 1.87 seconds)832server: must succeed: systemctl kill -s KILL hold-lock833server # [ 175.060009] systemd[1]: hold-lock.service: Sent signal SIGKILL to main process 1506 (drive) on client request.834server # [ 175.078685] systemd[1]: hold-lock.service: Killed unit cgroup '/system.slice/hold-lock.service' with SIGKILL on client request.835server # [ 175.123100] systemd[1]: hold-lock.service: Main process exited, code=killed, status=9/KILL836server # [ 175.153422] systemd[1]: hold-lock.service: Failed with result 'signal'.837server: (finished: must succeed: systemctl kill -s KILL hold-lock, in 0.57 seconds)838server: waiting for failure: systemctl is-active --quiet hold-lock839server: (finished: waiting for failure: systemctl is-active --quiet hold-lock, in 0.60 seconds)840server: must succeed: runuser -u postgres -- /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/pg_ctl start -D /var/lib/postgresql/data -w -s -l /tmp/pg_ctl.log 841server # [ 176.295368] runuser[1579]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)842server # pg_ctl: another server might be running; trying to start server anyway843server # [ 178.167580] runuser[1579]: pam_unix(runuser:session): session closed for user postgres844server: (finished: must succeed: runuser -u postgres -- /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/pg_ctl start -D /var/lib/postgresql/data -w -s -l /tmp/pg_ctl.log , in 2.43 seconds)845server: must succeed: runuser -u postgres -- /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/pg_ctl stop -D /var/lib/postgresql/data -w -s 846server # [ 178.648873] runuser[1606]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)847server # [ 179.052772] runuser[1606]: pam_unix(runuser:session): session closed for user postgres848server: (finished: must succeed: runuser -u postgres -- /nix/store/1zk32bp26apmbl88jx2hy94jccll7bp8-postgresql-and-plugins-15.19/bin/pg_ctl stop -D /var/lib/postgresql/data -w -s , in 0.92 seconds)849server: must succeed: rm -f /run/pg-upgrade-source.pid850server: (finished: must succeed: rm -f /run/pg-upgrade-source.pid, in 0.47 seconds)851server: must succeed: systemctl start postgresql852server # [ 180.247146] systemd[1]: Starting postgresql.service...853server # [ 181.399686] postgres[1628]: 2026-10-22 21:32:04.627 UTC [1628] LOG: starting PostgreSQL 15.19 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 15.2.0, 64-bit854server # [ 181.414545] postgres[1628]: 2026-10-22 21:32:04.649 UTC [1628] LOG: listening on IPv6 address "::1", port 5432855server # [ 181.415330] postgres[1628]: 2026-10-22 21:32:04.650 UTC [1628] LOG: listening on IPv4 address "127.0.0.1", port 5432856server # [ 181.430843] postgres[1628]: 2026-10-22 21:32:04.668 UTC [1628] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"857server # [ 181.524242] postgres[1637]: 2026-10-22 21:32:04.757 UTC [1637] LOG: database system was shut down at 2026-10-22 21:32:02 UTC858server # [ 181.637159] postgres[1628]: 2026-10-22 21:32:04.874 UTC [1628] LOG: database system is ready to accept connections859server # [ 181.675324] systemd[1]: Started postgresql.service.860server: (finished: must succeed: systemctl start postgresql, in 2.13 seconds)861server: waiting for unit postgresql.service862server: (finished: waiting for unit postgresql.service, in 0.53 seconds)863(finished: subtest: The pid lock stops a direct start once the new cluster is up, in 15.02 seconds)864subtest: A real pg_upgrade copy under a start storm865server: must succeed: systemd-run --unit=fake-initiate --collect --pipe --wait /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive upgrade866server # [ 182.819366] systemd[1]: Started [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive upgrade.867server # Running as unit: fake-initiate.service; invocation ID: 0a2da62833494a2c878a32cad18b616b868server # [ 183.436645] systemd[1]: Stopping postgresql.service...869server # [ 183.440202] postgres[1628]: 2026-10-22 21:32:06.672 UTC [1628] LOG: received fast shutdown request870server # [ 183.476853] postgres[1628]: 2026-10-22 21:32:06.704 UTC [1628] LOG: aborting any active transactions871server # [ 183.544597] postgres[1628]: 2026-10-22 21:32:06.777 UTC [1628] LOG: background worker "logical replication launcher" (PID 1640) exited with exit code 1872server # [ 183.563518] postgres[1635]: 2026-10-22 21:32:06.795 UTC [1635] LOG: shutting down873server # [ 183.585259] postgres[1635]: 2026-10-22 21:32:06.819 UTC [1635] LOG: checkpoint starting: shutdown immediate874server # [ 183.649882] postgres[1635]: 2026-10-22 21:32:06.887 UTC [1635] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.017 s, sync=0.009 s, total=0.085 s; sync files=2, longest=0.006 s, average=0.005 s; distance=0 kB, estimate=0 kB875server # [ 183.710010] postgres[1628]: 2026-10-22 21:32:06.944 UTC [1628] LOG: database system is shut down876server # [ 183.755725] systemd[1]: postgresql.service: Deactivated successfully.877server # [ 183.769305] systemd[1]: Stopped postgresql.service.878server # [ 184.156720] systemd[1]: Reload requested from client PID 1672 ('systemctl') (unit fake-initiate.service)...879server # [ 184.169493] systemd[1]: Reloading...880server # [ 190.567968] systemd[1]: Reloading finished in 6423 ms.881server # [ 191.178512] runuser[1702]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)882server # [ 204.400643] input: QEMU Virtio Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:08.0/virtio7/input/input3883server # [ 214.227862] systemd[1]: Starting Virtual Console Setup...884server # [ 214.578046] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.885server # [ 214.612174] systemd[1]: Stopped Virtual Console Setup.886server # [ 214.651030] systemd[1]: Starting Virtual Console Setup...887server # [ 219.502504] systemd[1]: Finished Virtual Console Setup.888server # [ 220.211170] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.889server # [ 223.218904] systemd-logind[628]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)890server # initdb: warning: enabling "trust" authentication for local connections891server # initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.892server # [ 224.051707] runuser[1702]: pam_unix(runuser:session): session closed for user postgres893server # [ 224.475591] systemd[1]: Started [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive salt_sim.894server # Running as unit: salt-sim.service; invocation ID: 2dbe38e18a954ec69172eb06167516a4895server # [ 225.075808] runuser[1863]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)896server # [ 225.402513] systemd[1]: Starting postgresql.service...897server # [ 226.283297] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION898server # [ 226.319811] systemd[1]: postgresql.service: Failed with result 'exit-code'.899server # [ 226.337760] systemd[1]: Failed to start postgresql.service.900server # [ 227.368026] systemd[1]: Starting postgresql.service...901server # [ 228.202095] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION902server # [ 228.215135] systemd[1]: postgresql.service: Failed with result 'exit-code'.903server # [ 228.235732] systemd[1]: Failed to start postgresql.service.904server # [ 229.250735] systemd[1]: Starting postgresql.service...905server # [ 229.823886] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION906server # [ 229.839551] systemd[1]: postgresql.service: Failed with result 'exit-code'.907server # [ 229.858129] systemd[1]: Failed to start postgresql.service.908server # [ 230.683920] systemd[1]: Starting postgresql.service...909server # [ 231.233491] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION910server # [ 231.245254] systemd[1]: postgresql.service: Failed with result 'exit-code'.911server # [ 231.261098] systemd[1]: Failed to start postgresql.service.912server # [ 232.039965] systemd[1]: Starting postgresql.service...913server # [ 232.596515] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION914server # [ 232.607495] systemd[1]: postgresql.service: Failed with result 'exit-code'.915server # [ 232.629518] systemd[1]: Failed to start postgresql.service.916server # [ 233.392628] systemd[1]: postgresql.service: Start request repeated too quickly.917server # [ 233.406891] systemd[1]: postgresql.service: Failed with result 'exit-code'.918server # [ 233.408309] systemd[1]: Failed to start postgresql.service.919server # [ 234.110285] systemd[1]: postgresql.service: Start request repeated too quickly.920server # [ 234.112422] systemd[1]: postgresql.service: Failed with result 'exit-code'.921server # [ 234.130198] systemd[1]: Failed to start postgresql.service.922server # [ 234.907634] systemd[1]: postgresql.service: Start request repeated too quickly.923server # [ 234.922439] systemd[1]: postgresql.service: Failed with result 'exit-code'.924server # [ 234.923443] systemd[1]: Failed to start postgresql.service.925server # [ 235.711407] systemd[1]: Starting postgresql.service...926server # [ 236.282249] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION927server # [ 236.283434] systemd[1]: postgresql.service: Failed with result 'exit-code'.928server # [ 236.322203] systemd[1]: Failed to start postgresql.service.929server # [ 237.097052] systemd[1]: Starting postgresql.service...930server # [ 237.619042] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION931server # [ 237.637268] systemd[1]: postgresql.service: Failed with result 'exit-code'.932server # [ 237.638591] systemd[1]: Failed to start postgresql.service.933server # [ 238.305009] systemd[1]: Starting postgresql.service...934server # [ 238.819451] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION935server # [ 238.853940] systemd[1]: postgresql.service: Failed with result 'exit-code'.936server # [ 238.854927] systemd[1]: Failed to start postgresql.service.937server # [ 239.541392] systemd[1]: Starting postgresql.service...938server # [ 240.044853] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION939server # [ 240.051449] systemd[1]: postgresql.service: Failed with result 'exit-code'.940server # [ 240.052118] systemd[1]: Failed to start postgresql.service.941server # [ 240.759235] systemd[1]: Starting postgresql.service...942server # [ 241.247516] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION943server # [ 241.279139] systemd[1]: postgresql.service: Failed with result 'exit-code'.944server # [ 241.286621] systemd[1]: Failed to start postgresql.service.945server # [ 241.881377] systemd[1]: postgresql.service: Start request repeated too quickly.946server # [ 241.882970] systemd[1]: postgresql.service: Failed with result 'exit-code'.947server # [ 241.883644] systemd[1]: Failed to start postgresql.service.948server # [ 242.520139] systemd[1]: postgresql.service: Start request repeated too quickly.949server # [ 242.539933] systemd[1]: postgresql.service: Failed with result 'exit-code'.950server # [ 242.558493] systemd[1]: Failed to start postgresql.service.951server # [ 243.159546] systemd[1]: postgresql.service: Start request repeated too quickly.952server # [ 243.167540] systemd[1]: postgresql.service: Failed with result 'exit-code'.953server # [ 243.187349] systemd[1]: Failed to start postgresql.service.954server # [ 243.841328] systemd[1]: postgresql.service: Start request repeated too quickly.955server # [ 243.862367] systemd[1]: postgresql.service: Failed with result 'exit-code'.956server # [ 243.863242] systemd[1]: Failed to start postgresql.service.957server # [ 244.566138] systemd[1]: postgresql.service: Start request repeated too quickly.958server # [ 244.575553] systemd[1]: postgresql.service: Failed with result 'exit-code'.959server # [ 244.594399] systemd[1]: Failed to start postgresql.service.960server # [ 245.315599] systemd[1]: postgresql.service: Start request repeated too quickly.961server # [ 245.342660] systemd[1]: postgresql.service: Failed with result 'exit-code'.962server # [ 245.343800] systemd[1]: Failed to start postgresql.service.963server # [ 246.138409] systemd[1]: Starting postgresql.service...964server # [ 246.657176] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION965server # [ 246.670499] systemd[1]: postgresql.service: Failed with result 'exit-code'.966server # [ 246.681838] systemd[1]: Failed to start postgresql.service.967server # [ 247.400662] systemd[1]: Starting postgresql.service...968server # [ 247.916625] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION969server # [ 247.930740] systemd[1]: postgresql.service: Failed with result 'exit-code'.970server # [ 247.931689] systemd[1]: Failed to start postgresql.service.971server # [ 248.605469] systemd[1]: Starting postgresql.service...972server # [ 249.099108] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION973server # [ 249.129054] systemd[1]: postgresql.service: Failed with result 'exit-code'.974server # [ 249.130269] systemd[1]: Failed to start postgresql.service.975server # [ 249.837670] systemd[1]: Starting postgresql.service...976server # [ 250.347766] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION977server # [ 250.383275] systemd[1]: postgresql.service: Failed with result 'exit-code'.978server # [ 250.392010] systemd[1]: Failed to start postgresql.service.979server # [ 251.083916] systemd[1]: Starting postgresql.service...980server # [ 251.585406] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION981server # [ 251.605024] systemd[1]: postgresql.service: Failed with result 'exit-code'.982server # [ 251.605974] systemd[1]: Failed to start postgresql.service.983server # [ 252.241467] systemd[1]: postgresql.service: Start request repeated too quickly.984server # [ 252.269198] systemd[1]: postgresql.service: Failed with result 'exit-code'.985server # [ 252.271521] systemd[1]: Failed to start postgresql.service.986server # [ 252.963618] systemd[1]: postgresql.service: Start request repeated too quickly.987server # [ 252.987040] systemd[1]: postgresql.service: Failed with result 'exit-code'.988server # [ 252.987775] systemd[1]: Failed to start postgresql.service.989server # [ 253.694850] systemd[1]: postgresql.service: Start request repeated too quickly.990server # [ 253.722610] systemd[1]: postgresql.service: Failed with result 'exit-code'.991server # [ 253.724126] systemd[1]: Failed to start postgresql.service.992server # [ 254.438045] systemd[1]: postgresql.service: Start request repeated too quickly.993server # [ 254.453352] systemd[1]: postgresql.service: Failed with result 'exit-code'.994server # [ 254.459758] systemd[1]: Failed to start postgresql.service.995server # [ 255.174961] systemd[1]: postgresql.service: Start request repeated too quickly.996server # [ 255.182127] systemd[1]: postgresql.service: Failed with result 'exit-code'.997server # [ 255.183052] systemd[1]: Failed to start postgresql.service.998server # [ 255.924572] systemd[1]: postgresql.service: Start request repeated too quickly.999server # [ 255.954509] systemd[1]: postgresql.service: Failed with result 'exit-code'.1000server # [ 255.955818] systemd[1]: Failed to start postgresql.service.1001server # [ 256.646341] systemd[1]: Starting postgresql.service...1002server # [ 257.189549] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1003server # [ 257.191019] systemd[1]: postgresql.service: Failed with result 'exit-code'.1004server # [ 257.191660] systemd[1]: Failed to start postgresql.service.1005server # [ 257.902035] systemd[1]: Starting postgresql.service...1006server # [ 258.423974] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1007server # [ 258.441408] systemd[1]: postgresql.service: Failed with result 'exit-code'.1008server # [ 258.442396] systemd[1]: Failed to start postgresql.service.1009server # [ 259.130415] systemd[1]: Starting postgresql.service...1010server # [ 259.630198] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1011server # [ 259.631406] systemd[1]: postgresql.service: Failed with result 'exit-code'.1012server # [ 259.670459] systemd[1]: Failed to start postgresql.service.1013server # [ 260.320306] systemd[1]: Starting postgresql.service...1014server # [ 260.779253] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1015server # [ 260.792643] systemd[1]: postgresql.service: Failed with result 'exit-code'.1016server # [ 260.814939] systemd[1]: Failed to start postgresql.service.1017server # [ 261.475563] systemd[1]: Starting postgresql.service...1018server # [ 261.959586] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1019server # [ 261.978247] systemd[1]: postgresql.service: Failed with result 'exit-code'.1020server # [ 261.979254] systemd[1]: Failed to start postgresql.service.1021server # [ 262.634773] systemd[1]: postgresql.service: Start request repeated too quickly.1022server # [ 262.645274] systemd[1]: postgresql.service: Failed with result 'exit-code'.1023server # [ 262.646400] systemd[1]: Failed to start postgresql.service.1024server # [ 263.260875] systemd[1]: postgresql.service: Start request repeated too quickly.1025server # [ 263.296803] systemd[1]: postgresql.service: Failed with result 'exit-code'.1026server # [ 263.298678] systemd[1]: Failed to start postgresql.service.1027server # [ 263.910056] systemd[1]: postgresql.service: Start request repeated too quickly.1028server # [ 263.914266] systemd[1]: postgresql.service: Failed with result 'exit-code'.1029server # [ 263.915043] systemd[1]: Failed to start postgresql.service.1030server # [ 264.586946] systemd[1]: postgresql.service: Start request repeated too quickly.1031server # [ 264.607022] systemd[1]: postgresql.service: Failed with result 'exit-code'.1032server # [ 264.607809] systemd[1]: Failed to start postgresql.service.1033server # [ 265.227202] systemd[1]: postgresql.service: Start request repeated too quickly.1034server # [ 265.246477] systemd[1]: postgresql.service: Failed with result 'exit-code'.1035server # [ 265.247539] systemd[1]: Failed to start postgresql.service.1036server # [ 265.867913] systemd[1]: postgresql.service: Start request repeated too quickly.1037server # [ 265.886281] systemd[1]: postgresql.service: Failed with result 'exit-code'.1038server # [ 265.887071] systemd[1]: Failed to start postgresql.service.1039server # [ 266.523654] systemd[1]: postgresql.service: Start request repeated too quickly.1040server # [ 266.533459] systemd[1]: postgresql.service: Failed with result 'exit-code'.1041server # [ 266.534469] systemd[1]: Failed to start postgresql.service.1042server # [ 267.325812] systemd[1]: Starting postgresql.service...1043server # [ 267.805348] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1044server # [ 267.806781] systemd[1]: postgresql.service: Failed with result 'exit-code'.1045server # [ 267.821510] systemd[1]: Failed to start postgresql.service.1046server # [ 268.551056] systemd[1]: Starting postgresql.service...1047server # [ 269.067844] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1048server # [ 269.083508] systemd[1]: postgresql.service: Failed with result 'exit-code'.1049server # [ 269.100826] systemd[1]: Failed to start postgresql.service.1050server # [ 269.835992] systemd[1]: Starting postgresql.service...1051server # [ 270.406275] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1052server # [ 270.407683] systemd[1]: postgresql.service: Failed with result 'exit-code'.1053server # [ 270.408266] systemd[1]: Failed to start postgresql.service.1054server # [ 271.121684] systemd[1]: Starting postgresql.service...1055server # [ 271.663902] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1056server # [ 271.675548] systemd[1]: postgresql.service: Failed with result 'exit-code'.1057server # [ 271.688463] systemd[1]: Failed to start postgresql.service.1058server # [ 272.516791] systemd[1]: Starting postgresql.service...1059server # [ 273.083439] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1060server # [ 273.106525] systemd[1]: postgresql.service: Failed with result 'exit-code'.1061server # [ 273.107455] systemd[1]: Failed to start postgresql.service.1062server # [ 273.739563] systemd[1]: postgresql.service: Start request repeated too quickly.1063server # [ 273.761678] systemd[1]: postgresql.service: Failed with result 'exit-code'.1064server # [ 273.762716] systemd[1]: Failed to start postgresql.service.1065server # [ 274.341078] systemd[1]: postgresql.service: Start request repeated too quickly.1066server # [ 274.342725] systemd[1]: postgresql.service: Failed with result 'exit-code'.1067server # [ 274.343587] systemd[1]: Failed to start postgresql.service.1068server # [ 275.031789] systemd[1]: postgresql.service: Start request repeated too quickly.1069server # [ 275.058558] systemd[1]: postgresql.service: Failed with result 'exit-code'.1070server # [ 275.059486] systemd[1]: Failed to start postgresql.service.1071server # [ 275.754289] systemd[1]: postgresql.service: Start request repeated too quickly.1072server # [ 275.757321] systemd[1]: postgresql.service: Failed with result 'exit-code'.1073server # [ 275.758320] systemd[1]: Failed to start postgresql.service.1074server # [ 276.419138] systemd[1]: postgresql.service: Start request repeated too quickly.1075server # [ 276.437821] systemd[1]: postgresql.service: Failed with result 'exit-code'.1076server # [ 276.439014] systemd[1]: Failed to start postgresql.service.1077server # [ 277.065106] systemd[1]: postgresql.service: Start request repeated too quickly.1078server # [ 277.082055] systemd[1]: postgresql.service: Failed with result 'exit-code'.1079server # [ 277.082913] systemd[1]: Failed to start postgresql.service.1080server # [ 277.842613] systemd[1]: Starting postgresql.service...1081server # [ 278.311904] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1082server # [ 278.326037] systemd[1]: postgresql.service: Failed with result 'exit-code'.1083server # [ 278.338452] systemd[1]: Failed to start postgresql.service.1084server # [ 279.030945] systemd[1]: Starting postgresql.service...1085server # [ 279.493442] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1086server # [ 279.518364] systemd[1]: postgresql.service: Failed with result 'exit-code'.1087server # [ 279.519926] systemd[1]: Failed to start postgresql.service.1088server # [ 280.201483] systemd[1]: Starting postgresql.service...1089server # [ 280.653360] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1090server # [ 280.654767] systemd[1]: postgresql.service: Failed with result 'exit-code'.1091server # [ 280.675651] systemd[1]: Failed to start postgresql.service.1092server # [ 281.379311] systemd[1]: Starting postgresql.service...1093server # [ 281.914741] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1094server # [ 281.923916] systemd[1]: postgresql.service: Failed with result 'exit-code'.1095server # [ 281.938545] systemd[1]: Failed to start postgresql.service.1096server # [ 282.615549] systemd[1]: Starting postgresql.service...1097server # [ 283.139627] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1098server # [ 283.146080] systemd[1]: postgresql.service: Failed with result 'exit-code'.1099server # [ 283.147316] systemd[1]: Failed to start postgresql.service.1100server # [ 283.926840] systemd[1]: postgresql.service: Start request repeated too quickly.1101server # [ 283.939556] systemd[1]: postgresql.service: Failed with result 'exit-code'.1102server # [ 283.954394] systemd[1]: Failed to start postgresql.service.1103server # [ 284.709672] systemd[1]: postgresql.service: Start request repeated too quickly.1104server # [ 284.714873] systemd[1]: postgresql.service: Failed with result 'exit-code'.1105server # [ 284.715627] systemd[1]: Failed to start postgresql.service.1106server # [ 285.439466] systemd[1]: postgresql.service: Start request repeated too quickly.1107server # [ 285.463227] systemd[1]: postgresql.service: Failed with result 'exit-code'.1108server # [ 285.464038] systemd[1]: Failed to start postgresql.service.1109server # [ 286.249516] systemd[1]: postgresql.service: Start request repeated too quickly.1110server # [ 286.258671] systemd[1]: postgresql.service: Failed with result 'exit-code'.1111server # [ 286.259399] systemd[1]: Failed to start postgresql.service.1112server # [ 287.294895] systemd[1]: postgresql.service: Start request repeated too quickly.1113server # [ 287.322380] systemd[1]: postgresql.service: Failed with result 'exit-code'.1114server # [ 287.323233] systemd[1]: Failed to start postgresql.service.1115server # [ 288.259735] systemd[1]: Starting postgresql.service...1116server # [ 288.835266] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1117server # [ 288.855940] systemd[1]: postgresql.service: Failed with result 'exit-code'.1118server # [ 288.871867] systemd[1]: Failed to start postgresql.service.1119server # [ 289.597390] systemd[1]: Starting postgresql.service...1120server # [ 290.355191] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1121server # [ 290.372613] systemd[1]: postgresql.service: Failed with result 'exit-code'.1122server # [ 290.399913] systemd[1]: Failed to start postgresql.service.1123server # [ 291.730313] systemd[1]: Starting postgresql.service...1124server # [ 292.366960] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION1125server # [ 292.386768] systemd[1]: postgresql.service: Failed with result 'exit-code'.1126server # [ 292.388386] systemd[1]: Failed to start postgresql.service.1127server # [ 293.050132] runuser[1863]: pam_unix(runuser:session): session closed for user postgres1128server # [ 293.267668] systemd[1]: Starting postgresql.service...1129server # [ 293.374990] systemd[1]: Stopping [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive salt_sim...1130server # [ 293.481646] systemd[1]: salt-sim.service: Deactivated successfully.1131server # [ 293.503115] systemd[1]: Stopped [systemd-run] /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive salt_sim.1132server # [ 293.504784] systemd[1]: salt-sim.service: Consumed 10.853s CPU time, 1.9M memory peak, 4K written to disk.1133server # [ 293.944667] systemd[1]: fake-initiate.service: Main process exited, code=exited, status=1/FAILURE1134server # [ 293.953906] systemd[1]: fake-initiate.service: Failed with result 'exit-code'.1135server # [ 293.977215] systemd[1]: fake-initiate.service: Consumed 38.715s CPU time, 148.3M memory peak, 238.2M written to disk.1136server # Finished with result: exit-code1137server # Main processes terminated with: code=exited, status=1/FAILURE1138server # Service runtime: 1min 51.154s1139server # CPU time consumed: 38.715s1140server # Memory peak: 148.3M (swap: 0B)1141server # IO Bytes: written 238.2M1142server: output: The files belonging to this database system will be owned by user "postgres".1143This user must also own the server process.11441145The database cluster will be initialized with locale "C".1146The default text search configuration will be set to "english".11471148Data page checksums are disabled.11491150creating directory /var/lib/postgresql/data-17 ... ok1151creating subdirectories ... ok1152selecting dynamic shared memory implementation ... posix1153selecting default "max_connections" ... 1001154selecting default "shared_buffers" ... 128MB1155selecting default time zone ... UTC1156creating configuration files ... ok1157running bootstrap script ... ok1158performing post-bootstrap initialization ... ok1159syncing data to disk ... ok116011611162Success. You can now start the database server using:11631164 /nix/store/0kc57vrr3jdbz3jqh7q142rdxndjs2b6-postgresql-and-plugins-17.11/bin/pg_ctl -D /var/lib/postgresql/data-17 -l logfile start11651166Performing Consistency Checks1167-----------------------------1168Checking cluster versions ok1169Checking database user is the install user ok1170Checking database connection settings ok1171Checking for prepared transactions ok1172Checking for contrib/isn with bigint-passing mismatch ok1173Checking data type usage ok1174Checking for not-null constraint inconsistencies ok1175Creating dump of global objects ok1176Creating dump of database schemas ok1177[21:33:21] Locked /var/lib/postgresql/data with pg_upgrade pid 18651178Checking for presence of required libraries ok1179Checking database user is the install user ok1180Checking for prepared transactions ok1181Checking for new cluster tablespace directories ok11821183If pg_upgrade fails after this point, you must re-initdb the1184new cluster before continuing.11851186Performing Upgrade1187------------------1188Setting locale and encoding for new cluster ok1189Analyzing all rows in the new cluster ok1190Freezing all rows in the new cluster ok1191Deleting files from new pg_xact ok1192Copying old pg_xact to new server ok1193Setting oldest XID for new cluster ok1194Setting next transaction ID and epoch for new cluster ok1195Deleting files from new pg_multixact/offsets ok1196Copying old pg_multixact/offsets to new server ok1197Deleting files from new pg_multixact/members ok1198Copying old pg_multixact/members to new server ok1199Setting next multixact ID and offset for new cluster ok1200Resetting WAL archives ok1201Setting frozenxid and minmxid counters in new cluster ok1202Restoring global objects in the new cluster ok1203Restoring database schemas in the new cluster ok1204Copying user relation files ok1205Setting next OID for new cluster ok1206Sync data directory to disk ok1207Creating script to delete old cluster ok1208Checking for extension updates ok12091210Upgrade Complete1211----------------1212Optimizer statistics are not transferred by pg_upgrade.1213Once you start the new server, consider running:1214 /nix/store/0kc57vrr3jdbz3jqh7q142rdxndjs2b6-postgresql-and-plugins-17.11/bin/vacuumdb -U postgres --all --analyze-in-stages1215Running this script will delete the old cluster's data files:1216 ./delete_old_cluster.sh1217[21:33:57] ERROR: postgresql.service is activating after pg_upgrade; the copied data files may be inconsistent12181219!!! Test "A real pg_upgrade copy under a start storm" failed with error: "command `systemd-run --unit=fake-initiate --collect --pipe --wait /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive upgrade` failed (exit code 1)"1220!!! Traceback (most recent call last):1221!!! File "<string>", line 69, in <module>1222!!! server.succeed(f"systemd-run --unit=fake-initiate --collect --pipe --wait {DRIVE} upgrade")1223!!! 1224!!! RequestedAssertionFailed: command `systemd-run --unit=fake-initiate --collect --pipe --wait /nix/store/m26c2dp1f4iqs75v00chi0v1bcqkys7g-drive/bin/drive upgrade` failed (exit code 1)1225cleanup1226kill machine (pid 9)1227qemu-system-aarch64: terminating on signal 15 from pid 6 (/nix/store/y88crn50yx35fiiwcjx6xqwi6ahk7mlq-python3-3.13.11/bin/python3.13)1228vde_switch: EOF data port: Interrupted system call1229kill vlan (pid 7)1230vde_switch: (finished: cleanup, in 0.01 seconds)1231Caught signal 15, cleaning up and exiting