Machine state will be reset. To keep it, pass --keep-vm-state
start all VLans
start vlan
running vlan (pid 7; ctl /build/vde1.ctl)
(finished: start all VLans, in 0.00 seconds)
Test will time out and terminate in 3600 seconds
run the VM test script
additionally exposed symbols:
    server,
    vlan1,
    start_all, test_script, machines, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, Machine, t, debug
start all VMs
server: starting vm
mke2fs 1.47.3 (8-Jul-2025)
qemu-system-aarch64: Could not access KVM kernel module: No such file or directory
qemu-system-aarch64: failed to initialize kvm: No such file or directory
qemu-system-aarch64: falling back to tcg
server # Disk image does not exist, creating the virtualisation disk image...
server # Formatting '/build/vm-state-server/tmp.e7Q3c6pMzp', fmt=raw size=4294967296
server # Discarding device blocks:       0/1048576               done
server # Creating filesystem with 1048576 4k blocks and 262144 inodes
server # Filesystem UUID: 530fc01f-9585-414d-8c3a-706a38c5f4f0
server # Superblock backups stored on blocks:
server # 	32768, 98304, 163840, 229376, 294912, 819200, 884736
server # 
server # Allocating group tables:  0/32     done
server # Writing inode tables:  0/32     done
server # Creating journal (16384 blocks): done
server # Writing superblocks and filesystem accounting information:  0/32     done
server # 
server # Virtualisation disk image created.
server: QEMU running (pid 9)
(finished: start all VMs, in 0.16 seconds)
server: waiting for unit postgresql.service
server: waiting for the VM to finish booting
server # [    0.000000] Booting Linux on physical CPU 0x0000000000 [0x000f0510]
server # [    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 2025
server # [    0.000000] KASLR enabled
server # [    0.000000] random: crng init done
server # [    0.000000] Machine model: linux,dummy-virt
server # [    0.000000] efi: UEFI not found.
server # [    0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT
server # [    0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000bfffffff]
server # [    0.000000] NODE_DATA(0) allocated [mem 0xbfa04780-0xbfa07ebf]
server # [    0.000000] Zone ranges:
server # [    0.000000]   DMA      [mem 0x0000000040000000-0x00000000bfffffff]
server # [    0.000000]   DMA32    empty
server # [    0.000000]   Normal   empty
server # [    0.000000]   Device   empty
server # [    0.000000] Movable zone start for each node
server # [    0.000000] Early memory node ranges
server # [    0.000000]   node   0: [mem 0x0000000040000000-0x00000000bfffffff]
server # [    0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000bfffffff]
server # [    0.000000] cma: Reserved 32 MiB at 0x00000000bb800000 on node -1
server # [    0.000000] psci: probing for conduit method from DT.
server # [    0.000000] psci: PSCIv1.1 detected in firmware.
server # [    0.000000] psci: Using standard PSCI v0.2 function IDs
server # [    0.000000] psci: Trusted OS migration not required
server # [    0.000000] psci: SMC Calling Convention v1.0
server # [    0.000000] percpu: Embedded 88 pages/cpu s180056 r65536 d114856 u360448
server # [    0.000000] Detected PIPT I-cache on CPU0
server # [    0.000000] CPU features: detected: Address authentication (IMP DEF algorithm)
server # [    0.000000] CPU features: detected: GIC system register CPU interface
server # [    0.000000] CPU features: detected: HCRX_EL2 register
server # [    0.000000] CPU features: detected: 52-bit Virtual Addressing (LPA2)
server # [    0.000000] CPU features: detected: Spectre-v4
server # [    0.000000] alternatives: applying boot alternatives
server # [    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/i7a98zy3i337z3yn9jxl1x2l93ixw8hh-nixos-system-server-test/init regInfo=/nix/store/bhac28dc391yq48czj2c4ja1ql71yizf-closure-info/registration console=ttyAMA0,115200n8 console=tty0
server # [    0.000000] Unknown kernel command line parameters "regInfo=/nix/store/bhac28dc391yq48czj2c4ja1ql71yizf-closure-info/registration", will be passed to user space.
server # [    0.000000] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
server # [    0.000000] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
server # [    0.000000] Fallback order for Node 0: 0
server # [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 524288
server # [    0.000000] Policy zone: DMA
server # [    0.000000] mem auto-init: stack:all(zero), heap alloc:on, heap free:off
server # [    0.000000] software IO TLB: SWIOTLB bounce buffer size adjusted to 2MB
server # [    0.000000] software IO TLB: area num 1.
server # [    0.000000] software IO TLB: mapped [mem 0x00000000bb25a000-0x00000000bb45a000] (2MB)
server # [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
server # [    0.000000] allocated 4194304 bytes of page_ext
server # [    0.000000] ftrace: allocating 72257 entries in 283 pages
server # [    0.000000] ftrace: allocated 283 pages with 5 groups
server # [    0.000000] rcu: Hierarchical RCU implementation.
server # [    0.000000] rcu: 	RCU event tracing is enabled.
server # [    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=1.
server # [    0.000000] 	Rude variant of Tasks RCU enabled.
server # [    0.000000] 	Tracing variant of Tasks RCU enabled.
server # [    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
server # [    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
server # [    0.000000] RCU Tasks Rude: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.
server # [    0.000000] RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.
server # [    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
server # [    0.000000] GICv3: 256 SPIs implemented
server # [    0.000000] GICv3: 0 Extended SPIs implemented
server # [    0.000000] Root IRQ handler: gic_handle_irq
server # [    0.000000] GICv3: GICv3 features: 16 PPIs
server # [    0.000000] GICv3: GICD_CTRL.DS=1, SCR_EL3.FIQ=0
server # [    0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a0000
server # [    0.000000] ITS [mem 0x08080000-0x0809ffff]
server # [    0.000000] ITS@0x0000000008080000: allocated 8192 Devices @446c0000 (indirect, esz 8, psz 64K, shr 1)
server # [    0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @446d0000 (flat, esz 8, psz 64K, shr 1)
server # [    0.000000] GICv3: using LPI property table @0x00000000446e0000
server # [    0.000000] GICv3: CPU0: using allocated LPI pending table @0x00000000446f0000
server # [    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
server # [    0.000000] arch_timer: cp15 timer(s) running at 1000.00MHz (virt).
server # [    0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
server # [    0.000039] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns
server # [    0.002068] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)
server # [    0.011754] Console: colour dummy device 80x25
server # [    0.013121] printk: legacy console [tty0] enabled
server # [    0.019072] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000)
server # [    0.019462] pid_max: default: 32768 minimum: 301
server # [    0.021217] LSM: initializing lsm=capability,landlock,yama,bpf
server # [    0.022326] landlock: Up and running.
server # [    0.022358] Yama: becoming mindful.
server # [    0.023724] LSM support for eBPF active
server # [    0.025945] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
server # [    0.026031] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
server # [    0.054261] cacheinfo: Unable to detect cache hierarchy for CPU 0
server # [    0.066600] rcu: Hierarchical SRCU implementation.
server # [    0.066693] rcu: 	Max phase no-delay instances is 1000.
server # [    0.075133] fsl-mc MSI: its@8080000 domain created
server # [    0.077811] EFI services will not be available.
server # [    0.079156] smp: Bringing up secondary CPUs ...
server # [    0.079763] smp: Brought up 1 node, 1 CPU
server # [    0.079811] SMP: Total of 1 processors activated.
server # [    0.079856] CPU: All CPU(s) started at EL1
server # [    0.080122] CPU features: detected: Branch Target Identification
server # [    0.080180] CPU features: detected: 32-bit EL0 Support
server # [    0.080212] CPU features: detected: 32-bit EL1 Support
server # [    0.080239] CPU features: detected: ARMv8.4 Translation Table Level
server # [    0.080277] CPU features: detected: Instruction cache invalidation not required for I/D coherence
server # [    0.080318] CPU features: detected: Data cache clean to the PoU not required for I/D coherence
server # [    0.080391] CPU features: detected: Common not Private translations
server # [    0.080417] CPU features: detected: CRC32 instructions
server # [    0.080441] CPU features: detected: Data cache clean to Point of Deep Persistence
server # [    0.080475] CPU features: detected: Data cache clean to Point of Persistence
server # [    0.080504] CPU features: detected: Data independent timing control (DIT)
server # [    0.080528] CPU features: detected: E0PD
server # [    0.080546] CPU features: detected: Enhanced Counter Virtualization
server # [    0.080569] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF)
server # [    0.080594] CPU features: detected: Enhanced Privileged Access Never
server # [    0.080617] CPU features: detected: Enhanced Virtualization Traps
server # [    0.080640] CPU features: detected: Fine Grained Traps
server # [    0.080705] CPU features: detected: Generic authentication (IMP DEF algorithm)
server # [    0.080794] CPU features: detected: RCpc load-acquire (LDAPR)
server # [    0.080838] CPU features: detected: 52-bit Virtual Addressing for KVM (LPA2)
server # [    0.080863] CPU features: detected: LSE atomic instructions
server # [    0.080885] CPU features: detected: Memory Copy and Memory Set instructions
server # [    0.080909] CPU features: detected: Privileged Access Never
server # [    0.080931] CPU features: detected: RAS Extension Support
server # [    0.080952] CPU features: detected: Random Number Generator
server # [    0.080973] CPU features: detected: Speculation barrier (SB)
server # [    0.080995] CPU features: detected: Stage-2 Force Write-Back
server # [    0.081018] CPU features: detected: Trap EL0 IMPLEMENTATION DEFINED functionality
server # [    0.081045] CPU features: detected: TLB range maintenance instructions
server # [    0.081068] CPU features: detected: WFx with timeout
server # [    0.081111] CPU features: detected: Speculative Store Bypassing Safe (SSBS)
server # [    0.081142] CPU features: detected: Scalable Vector Extension
server # [    0.091415] alternatives: applying system-wide alternatives
server # [    0.105586] CPU features: detected: Hardware dirty bit management on CPU0
server # [    0.106238] SVE: maximum available vector length 256 bytes per vector
server # [    0.106343] SVE: default vector length 64 bytes per vector
server # [    0.118244] Memory: 1935376K/2097152K available (23296K kernel code, 6546K rwdata, 24596K rodata, 4416K init, 1047K bss, 118632K reserved, 32768K cma-reserved)
server # [    0.139744] devtmpfs: initialized
server # [    0.164533] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
server # [    0.165022] futex hash table entries: 256 (order: 2, 16384 bytes, linear)
server # [    0.168064] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL
server # [    0.168140] 0 pages in range for non-PLT usage
server # [    0.168178] 509248 pages in range for PLT usage
server # [    0.170924] pinctrl core: initialized pinctrl subsystem
server # [    0.181713] DMI not present or invalid.
server # [    0.199131] NET: Registered PF_NETLINK/PF_ROUTE protocol family
server # [    0.210045] DMA: preallocated 256 KiB GFP_KERNEL pool for atomic allocations
server # [    0.212653] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
server # [    0.215189] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
server # [    0.215473] audit: initializing netlink subsys (disabled)
server # [    0.217672] audit: type=2000 audit(0.180:1): state=initialized audit_enabled=0 res=1
server # [    0.224498] thermal_sys: Registered thermal governor 'fair_share'
server # [    0.224557] thermal_sys: Registered thermal governor 'bang_bang'
server # [    0.224616] thermal_sys: Registered thermal governor 'step_wise'
server # [    0.224649] thermal_sys: Registered thermal governor 'user_space'
server # [    0.224678] thermal_sys: Registered thermal governor 'power_allocator'
server # [    0.225183] cpuidle: using governor ladder
server # [    0.225350] cpuidle: using governor menu
server # [    0.227430] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
server # [    0.227865] ASID allocator initialised with 65536 entries
server # [    0.235315] Serial: AMBA PL011 UART driver
server # [    0.287393] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 13, base_baud = 0) is a PL011 rev1
server # [    0.288624] printk: legacy console [ttyAMA0] enabled
server # [    0.329232] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
server # [    0.329440] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page
server # [    0.329582] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages
server # [    0.329813] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page
server # [    0.329956] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages
server # [    0.330064] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page
server # [    0.330167] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages
server # [    0.330269] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page
server # [    0.358064] fbcon: Taking over console
server # [    0.358445] ACPI: Interpreter disabled.
server # [    0.370449] iommu: Default domain type: Translated
server # [    0.370626] iommu: DMA domain TLB invalidation policy: strict mode
server # [    0.377752] SCSI subsystem initialized
server # [    0.380972] usbcore: registered new interface driver usbfs
server # [    0.381486] usbcore: registered new interface driver hub
server # [    0.381721] usbcore: registered new device driver usb
server # [    0.383959] pps_core: LinuxPPS API ver. 1 registered
server # [    0.384131] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
server # [    0.384322] PTP clock support registered
server # [    0.389943] EDAC MC: Ver: 3.0.0
server # [    0.393694] scmi_core: SCMI protocol bus registered
server # [    0.399058] FPGA manager framework
server # [    0.400296] Advanced Linux Sound Architecture Driver Initialized.
server # [    0.421561] vgaarb: loaded
server # [    0.434815] clocksource: Switched to clocksource arch_sys_counter
server # [    0.439245] VFS: Disk quotas dquot_6.6.0
server # [    0.439469] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
server # [    0.443056] netfs: FS-Cache loaded
server # [    0.444429] pnp: PnP ACPI: disabled
server # [    0.490061] NET: Registered PF_INET protocol family
server # [    0.494399] IP idents hash table entries: 32768 (order: 6, 262144 bytes, linear)
server # [    0.627299] tcp_listen_portaddr_hash hash table entries: 1024 (order: 2, 16384 bytes, linear)
server # [    0.627811] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
server # [    0.628155] TCP established hash table entries: 16384 (order: 5, 131072 bytes, linear)
server # [    0.628773] TCP bind hash table entries: 16384 (order: 7, 524288 bytes, linear)
server # [    0.630009] TCP: Hash tables configured (established 16384 bind 16384)
server # [    0.631534] MPTCP token hash table entries: 2048 (order: 4, 49152 bytes, linear)
server # [    0.632150] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear)
server # [    0.632521] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear)
server # [    0.634506] NET: Registered PF_UNIX/PF_LOCAL protocol family
server # [    0.634986] NET: Registered PF_XDP protocol family
server # [    0.635194] PCI: CLS 0 bytes, default 64
server # [    0.638295] kvm [1]: HYP mode not available
server # [    0.642787] Trying to unpack rootfs image as initramfs...
server # [    0.828665] Initialise system trusted keyrings
server # [    0.834175] workingset: timestamp_bits=42 max_order=19 bucket_order=0
server # [    0.843234] squashfs: version 4.0 (2009/01/31) Phillip Lougher
server # [    0.844524] 9p: Installing v9fs 9p2000 file system support
server # [    0.979941] Key type asymmetric registered
server # [    0.980349] Asymmetric key parser 'x509' registered
server # [    0.981487] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 244)
server # [    0.982618] io scheduler mq-deadline registered
server # [    0.982964] io scheduler kyber registered
server # [    1.038968] pl061_gpio 9030000.pl061: PL061 GPIO chip registered
server # [    1.046944] ledtrig-cpu: registered to indicate activity on CPUs
server # [    1.056423] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:
server # [    1.057645] pci-host-generic 4010000000.pcie:       IO 0x003eff0000..0x003effffff -> 0x0000000000
server # [    1.058517] pci-host-generic 4010000000.pcie:      MEM 0x0010000000..0x003efeffff -> 0x0010000000
server # [    1.058735] pci-host-generic 4010000000.pcie:      MEM 0x8000000000..0xffffffffff -> 0x8000000000
server # [    1.059318] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits
server # [    1.060151] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]
server # [    1.066419] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00
server # [    1.067235] pci_bus 0000:00: root bus resource [bus 00-ff]
server # [    1.067507] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
server # [    1.067724] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]
server # [    1.067855] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]
server # [    1.069065] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint
server # [    1.076467] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint
server # [    1.077206] pci 0000:00:01.0: BAR 0 [io  0x0000-0x001f]
server # [    1.077550] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.077707] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.077879] pci 0000:00:01.0: ROM [mem 0x00000000-0x0003ffff pref]
server # [    1.081410] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint
server # [    1.081651] pci 0000:00:02.0: BAR 0 [io  0x0000-0x001f]
server # [    1.081887] pci 0000:00:02.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.082016] pci 0000:00:02.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.082532] pci 0000:00:03.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint
server # [    1.082830] pci 0000:00:03.0: BAR 0 [io  0x0000-0x003f]
server # [    1.082946] pci 0000:00:03.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.083065] pci 0000:00:03.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.083564] pci 0000:00:04.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint
server # [    1.084067] pci 0000:00:04.0: BAR 0 [io  0x0000-0x001f]
server # [    1.084176] pci 0000:00:04.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.084646] pci 0000:00:04.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.090767] pci 0000:00:05.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint
server # [    1.090978] pci 0000:00:05.0: BAR 0 [io  0x0000-0x001f]
server # [    1.091179] pci 0000:00:05.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.091430] pci 0000:00:05.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.092103] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint
server # [    1.092687] pci 0000:00:06.0: BAR 0 [io  0x0000-0x007f]
server # [    1.093219] pci 0000:00:06.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.093559] pci 0000:00:06.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.100803] pci 0000:00:07.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint
server # [    1.101035] pci 0000:00:07.0: BAR 0 [io  0x0000-0x001f]
server # [    1.101150] pci 0000:00:07.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.101326] pci 0000:00:07.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.102067] pci 0000:00:07.0: ROM [mem 0x00000000-0x0003ffff pref]
server # [    1.102662] pci 0000:00:08.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint
server # [    1.102844] pci 0000:00:08.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.102976] pci 0000:00:08.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.103531] pci 0000:00:09.0: [1af4:1050] type 00 class 0x038000 conventional PCI endpoint
server # [    1.103842] pci 0000:00:09.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.103968] pci 0000:00:09.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.104526] pci 0000:00:0a.0: [8086:24cd] type 00 class 0x0c0320 conventional PCI endpoint
server # [    1.104801] pci 0000:00:0a.0: BAR 0 [mem 0x00000000-0x00000fff]
server # [    1.109865] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint
server # [    1.110103] pci 0000:00:0b.0: BAR 0 [io  0x0000-0x003f]
server # [    1.110398] pci 0000:00:0b.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.110580] pci 0000:00:0b.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.111055] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint
server # [    1.111299] pci 0000:00:0c.0: BAR 0 [io  0x0000-0x001f]
server # [    1.111408] pci 0000:00:0c.0: BAR 1 [mem 0x00000000-0x00000fff]
server # [    1.111535] pci 0000:00:0c.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
server # [    1.113561] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned
server # [    1.113826] pci 0000:00:07.0: ROM [mem 0x10040000-0x1007ffff pref]: assigned
server # [    1.114027] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned
server # [    1.114331] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned
server # [    1.114503] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned
server # [    1.114720] pci 0000:00:04.0: BAR 4 [mem 0x800000c000-0x800000ffff 64bit pref]: assigned
server # [    1.114856] pci 0000:00:05.0: BAR 4 [mem 0x8000010000-0x8000013fff 64bit pref]: assigned
server # [    1.114990] pci 0000:00:06.0: BAR 4 [mem 0x8000014000-0x8000017fff 64bit pref]: assigned
server # [    1.115146] pci 0000:00:07.0: BAR 4 [mem 0x8000018000-0x800001bfff 64bit pref]: assigned
server # [    1.115295] pci 0000:00:08.0: BAR 4 [mem 0x800001c000-0x800001ffff 64bit pref]: assigned
server # [    1.116084] pci 0000:00:09.0: BAR 4 [mem 0x8000020000-0x8000023fff 64bit pref]: assigned
server # [    1.116240] pci 0000:00:0b.0: BAR 4 [mem 0x8000024000-0x8000027fff 64bit pref]: assigned
server # [    1.116497] pci 0000:00:0c.0: BAR 4 [mem 0x8000028000-0x800002bfff 64bit pref]: assigned
server # [    1.117406] pci 0000:00:01.0: BAR 1 [mem 0x10080000-0x10080fff]: assigned
server # [    1.117617] pci 0000:00:02.0: BAR 1 [mem 0x10081000-0x10081fff]: assigned
server # [    1.117807] pci 0000:00:03.0: BAR 1 [mem 0x10082000-0x10082fff]: assigned
server # [    1.118104] pci 0000:00:04.0: BAR 1 [mem 0x10083000-0x10083fff]: assigned
server # [    1.118227] pci 0000:00:05.0: BAR 1 [mem 0x10084000-0x10084fff]: assigned
server # [    1.118338] pci 0000:00:06.0: BAR 1 [mem 0x10085000-0x10085fff]: assigned
server # [    1.118444] pci 0000:00:07.0: BAR 1 [mem 0x10086000-0x10086fff]: assigned
server # [    1.118553] pci 0000:00:08.0: BAR 1 [mem 0x10087000-0x10087fff]: assigned
server # [    1.118674] pci 0000:00:09.0: BAR 1 [mem 0x10088000-0x10088fff]: assigned
server # [    1.118780] pci 0000:00:0a.0: BAR 0 [mem 0x10089000-0x10089fff]: assigned
server # [    1.118943] pci 0000:00:0b.0: BAR 1 [mem 0x1008a000-0x1008afff]: assigned
server # [    1.119172] pci 0000:00:0c.0: BAR 1 [mem 0x1008b000-0x1008bfff]: assigned
server # [    1.119297] pci 0000:00:06.0: BAR 0 [io  0x1000-0x107f]: assigned
server # [    1.119422] pci 0000:00:03.0: BAR 0 [io  0x1080-0x10bf]: assigned
server # [    1.119539] pci 0000:00:0b.0: BAR 0 [io  0x10c0-0x10ff]: assigned
server # [    1.119899] pci 0000:00:01.0: BAR 0 [io  0x1100-0x111f]: assigned
server # [    1.120004] pci 0000:00:02.0: BAR 0 [io  0x1120-0x113f]: assigned
server # [    1.120105] pci 0000:00:04.0: BAR 0 [io  0x1140-0x115f]: assigned
server # [    1.120210] pci 0000:00:05.0: BAR 0 [io  0x1160-0x117f]: assigned
server # [    1.120380] pci 0000:00:07.0: BAR 0 [io  0x1180-0x119f]: assigned
server # [    1.120484] pci 0000:00:0c.0: BAR 0 [io  0x11a0-0x11bf]: assigned
server # [    1.120798] pci_bus 0000:00: resource 4 [io  0x0000-0xffff]
server # [    1.120911] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]
server # [    1.121658] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]
server # [    1.132109] pci 0000:00:0a.0: enabling device (0000 -> 0002)
server # [    1.251827] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)
server # [    1.260208] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)
server # [    1.267148] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)
server # [    1.268674] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)
server # [    1.274183] virtio-pci 0000:00:05.0: enabling device (0000 -> 0003)
server # [    1.275862] virtio-pci 0000:00:06.0: enabling device (0000 -> 0003)
server # [    1.283129] virtio-pci 0000:00:07.0: enabling device (0000 -> 0003)
server # [    1.284677] virtio-pci 0000:00:08.0: enabling device (0000 -> 0002)
server # [    1.289811] virtio-pci 0000:00:09.0: enabling device (0000 -> 0002)
server # [    1.291688] virtio-pci 0000:00:0b.0: enabling device (0000 -> 0003)
server # [    1.298209] virtio-pci 0000:00:0c.0: enabling device (0000 -> 0003)
server # [    1.328387] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
server # [    1.346658] msm_serial: driver initialized
server # [    1.347450] SuperH (H)SCI(F) driver initialized
server # [    1.348289] STM32 USART driver initialized
server # [    1.443638] loop: module loaded
server # [    1.444380] virtio_blk virtio5: 1/0/0 default/read/poll queues
server # [    1.452049] virtio_blk virtio5: [vda] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB)
server # [    1.485845] megasas: 07.727.03.00-rc1
server # [    1.495263] Freeing initrd memory: 10684K
server # [    1.498217] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]
server # [    1.500734] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000
server # [    1.502145] Intel/Sharp Extended Query Table at 0x0031
server # [    1.503179] Using buffer write method
server # [    1.503896] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]
server # [    1.505939] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000
server # [    1.506188] Intel/Sharp Extended Query Table at 0x0031
server # [    1.507324] Using buffer write method
server # [    1.507836] Concatenating MTD devices:
server # [    1.507972] (0): "0.flash"
server # [    1.508032] (1): "0.flash"
server # [    1.508093] into device "0.flash"
server # [    1.530592] tun: Universal TUN/TAP device driver, 1.6
server # [    1.542748] thunder_xcv, ver 1.0
server # [    1.542993] thunder_bgx, ver 1.0
server # [    1.543167] nicpf, ver 1.0
server # [    1.546276] hns3: Hisilicon Ethernet Network Driver for Hip08 Family - version
server # [    1.546580] hns3: Copyright (c) 2017 Huawei Corporation.
server # [    1.547204] hclge is initializing
server # [    1.547430] e1000: Intel(R) PRO/1000 Network Driver
server # [    1.547514] e1000: Copyright (c) 1999-2006 Intel Corporation.
server # [    1.547966] e1000e: Intel(R) PRO/1000 Network Driver
server # [    1.548061] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
server # [    1.548379] igb: Intel(R) Gigabit Ethernet Network Driver
server # [    1.548483] igb: Copyright (c) 2007-2014 Intel Corporation.
server # [    1.548706] igbvf: Intel(R) Gigabit Virtual Function Network Driver
server # [    1.549236] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
server # [    1.550018] sky2: driver version 1.30
server # [    1.557706] ehci-pci 0000:00:0a.0: EHCI Host Controller
server # [    1.558234] ehci-pci 0000:00:0a.0: new USB bus registered, assigned bus number 1
server # [    1.560730] ehci-pci 0000:00:0a.0: irq 15, io mem 0x10089000
server # [    1.564123] usbcore: registered new interface driver usb-storage
server # [    1.564771] usbcore: registered new interface driver usbserial_generic
server # [    1.566081] usbserial: USB Serial support registered for generic
server # [    1.569224] ehci-pci 0000:00:0a.0: USB 2.0 started, EHCI 1.00
server # [    1.580757] rtc-pl031 9010000.pl031: registered as rtc0
server # [    1.582547] hub 1-0:1.0: USB hub found
server # [    1.583390] rtc-pl031 9010000.pl031: setting system clock to 2026-10-26T13:07:21 UTC (1793020041)
server # [    1.585464] hub 1-0:1.0: 6 ports detected
server # [    1.587976] i2c_dev: i2c /dev entries driver
server # [    1.603103] sdhci: Secure Digital Host Controller Interface driver
server # [    1.603289] sdhci: Copyright(c) Pierre Ossman
server # [    1.605009] Synopsys Designware Multimedia Card Interface Driver
server # [    1.607217] sdhci-pltfm: SDHCI platform and OF driver helper
server # [    1.614713] hid: raw HID events driver (C) Jiri Kosina
server # [    1.616894] usbcore: registered new interface driver usbhid
server # [    1.617046] usbhid: USB HID core driver
server # [    1.626167] hw perfevents: enabled with armv8_pmuv3 PMU driver, 7 (0,8000003f) counters available
server # [    1.639097] drop_monitor: Initializing network drop monitor service
server # [    1.640600] NET: Registered PF_INET6 protocol family
server # [    1.651956] Segment Routing with IPv6
server # [    1.652274] In-situ OAM (IOAM) with IPv6
server # [    1.652834] NET: Registered PF_PACKET protocol family
server # [    1.654237] 9pnet: Installing 9P2000 support
server # [    1.658713] Key type dns_resolver registered
server # [    1.697681] registered taskstats version 1
server # [    1.699949] Loading compiled-in X.509 certificates
server # [    1.755134] Demotion targets for Node 0: null
server # [    1.757115] Key type .fscrypt registered
server # [    1.757403] Key type fscrypt-provisioning registered
server # [    1.765259] input: gpio-keys as /devices/platform/gpio-keys/input/input0
server # [    1.807763] clk: Disabling unused clocks
server # [    1.808052] PM: genpd: Disabling unused power domains
server # [    1.808345] ALSA device list:
server # [    1.808446]   No soundcards found.
server # [    1.869974] Freeing unused kernel memory: 4416K
server # [    1.870448] usb 1-1: new high-speed USB device number 2 using ehci-pci
server # [    1.873764] Run /init as init process
server # [    2.042687] 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/input1
server # [    2.138298] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:0a.0-1/input0
server # [    2.257444] usb 1-2: new high-speed USB device number 3 using ehci-pci
server # [    2.376511] device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev
server # [    2.432711] 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/input2
server # [    2.438585] hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:0a.0-2/input0
server # [    2.519730] [drm] pci: virtio-gpu-pci detected at 0000:00:09.0
server # [    2.520407] [drm] features: -virgl +edid -resource_blob -host_visible
server # [    2.520430] [drm] features: -context_init
server # [    2.522936] [drm] number of scanouts: 1
server # [    2.523065] [drm] number of cap sets: 0
server # [    2.534639] [drm] Initialized virtio_gpu 0.1.0 for 0000:00:09.0 on minor 0
server # [    2.567980] Console: switching to colour frame buffer device 160x50
server # [    2.580023] virtio-pci 0000:00:09.0: [drm] fb0: virtio_gpudrmfb frame buffer device
server # [    6.063256] EXT4-fs (vda): mounted filesystem 530fc01f-9585-414d-8c3a-706a38c5f4f0 r/w with ordered data mode. Quota mode: none.
server # [    8.117932] EXT4-fs (vda): re-mounted 530fc01f-9585-414d-8c3a-706a38c5f4f0.
server # [    8.135402] booting system configuration /nix/store/i7a98zy3i337z3yn9jxl1x2l93ixw8hh-nixos-system-server-test
server # [   19.464968] 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)
server # [   19.475224] systemd[1]: Detected virtualization qemu.
server # [   19.480033] systemd[1]: Detected architecture arm64.
server # [   19.485462] systemd[1]: Detected first boot.
server # [   19.516223] systemd[1]: Initializing machine ID from random generator.
server # [   19.549900] systemd[1]: Hostname set to <server>.
server # [   20.767069] systemd[1]: bpf-restrict-fs: LSM BPF program attached
server # [   22.492198] systemd[1]: Applying preset policy.
server # [   25.941315] systemd[1]: Populated /etc with preset unit settings.
server # [   29.216163] systemd[1]: Queued start job for default target Multi-User System.
server # [   29.401233] systemd[1]: Created slice Slice /system/getty.
server # [   29.415314] systemd[1]: Created slice Slice /system/modprobe.
server # [   29.431154] systemd[1]: Created slice User and Session Slice.
server # [   29.439140] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
server # [   29.444702] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
server # [   29.449691] systemd[1]: Expecting device /dev/hvc0...
server # [   29.454106] systemd[1]: Expecting device /dev/ttyAMA0...
server # [   29.457895] systemd[1]: Expecting device /sys/subsystem/net/devices/eth1...
server # [   29.462874] systemd[1]: Reached target Local Encrypted Volumes.
server # [   29.467732] systemd[1]: Reached target Virtual Machines and Containers.
server # [   29.472126] systemd[1]: Reached target Path Units.
server # [   29.476460] systemd[1]: Reached target Remote File Systems.
server # [   29.480501] systemd[1]: Reached target Slice Units.
server # [   29.484539] systemd[1]: Reached target Swaps.
server # [   29.518109] systemd[1]: Listening on Process Core Dump Socket.
server # [   29.539290] systemd[1]: Listening on Credential Encryption/Decryption.
server # [   29.550089] systemd[1]: Listening on Journal Audit Socket.
server # [   29.556641] systemd[1]: Listening on Journal Socket (/dev/log).
server # [   29.563083] systemd[1]: Listening on Journal Sockets.
server # [   29.570825] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.
server # [   29.575930] systemd[1]: Make TPM PCR Policy was skipped because of an unmet condition check (ConditionSecurity=measured-uki).
server # [   29.581885] systemd[1]: Listening on udev Control Socket.
server # [   29.586816] systemd[1]: Listening on udev Kernel Socket.
server # [   29.632557] systemd[1]: Mounting Huge Pages File System...
server # [   29.694538] systemd[1]: Mounting POSIX Message Queue File System...
server: Guest root shell did not produce any data yet...
server:   To debug, enter the VM and run 'systemctl status backdoor.service'.
server # [   29.770519] systemd[1]: Mounting Kernel Debug File System...
server # [   29.878786] systemd[1]: Mounting Kernel Trace File System...
server # [   30.032314] systemd[1]: Starting Create List of Static Device Nodes...
server # [   30.187194] systemd[1]: Starting Load Kernel Module 9pnet_virtio...
server # [   30.216673] systemd[1]: Load Kernel Module configfs was skipped because of an unmet condition check (ConditionKernelModuleLoaded=!configfs).
server # [   30.342359] systemd[1]: Mounting Kernel Configuration File System...
server # [   30.366461] systemd[1]: Load Kernel Module drm was skipped because of an unmet condition check (ConditionKernelModuleLoaded=!drm).
server # [   30.396109] systemd[1]: Load Kernel Module efi_pstore was skipped because of an unmet condition check (ConditionKernelModuleLoaded=!efi_pstore).
server # [   30.534783] systemd[1]: Starting Load Kernel Module fuse...
server # [   30.548576] systemd[1]: File System Check on Root Device was skipped because of an unmet condition check (ConditionPathIsReadWrite=!/).
server # [   30.562987] 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).
server # [   30.684684] systemd[1]: Starting Journal Service...
server # [   30.743182] systemd[1]: Starting Load Kernel Modules...
server # [   30.828677] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...
server # [   30.902873] systemd[1]: Starting Remount Root and Kernel File Systems...
server # [   30.911366] systemd[1]: Early TPM SRK Setup was skipped because of an unmet condition check (ConditionSecurity=measured-uki).
server # [   30.994400] systemd[1]: Starting Coldplug All udev Devices...
server # [   31.068601] systemd[1]: Mounted Huge Pages File System.
server # [   31.082691] systemd[1]: Mounted POSIX Message Queue File System.
server # [   31.091033] systemd[1]: Mounted Kernel Debug File System.
server # [   31.099225] systemd[1]: Mounted Kernel Trace File System.
server # [   31.129774] systemd[1]: Finished Create List of Static Device Nodes.
server # [   31.148096] systemd[1]: Mounted Kernel Configuration File System.
server # [   31.214989] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...
server # [   32.243160] EXT4-fs (vda): re-mounted 530fc01f-9585-414d-8c3a-706a38c5f4f0.
server # [   32.337864] systemd[1]: Finished Load Kernel Modules.
server # [   32.404391] systemd[1]: Starting Firewall...
server # [   32.475956] systemd[1]: Starting Apply Kernel Variables...
server # [   32.502576] systemd[1]: Finished Remount Root and Kernel File Systems.
server # [   32.511160] systemd[1]: Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore).
server # [   32.596055] systemd[1]: Starting Load/Save OS Random Seed...
server # [   32.604472] systemd[1]: TPM SRK Setup was skipped because of an unmet condition check (ConditionSecurity=measured-uki).
server # [   32.646286] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.
server # [   32.661063] systemd[1]: Finished Load Kernel Module 9pnet_virtio.
server # [   33.220648] fuse: init (API version 7.41)
server # [   33.327062] systemd-journald[374]: Collecting audit messages is enabled.
server # [   33.353355] systemd[1]: modprobe@fuse.service: Deactivated successfully.
server # [   33.370496] systemd[1]: Finished Load Kernel Module fuse.
server # [   33.423136] systemd[1]: Mounting FUSE Control File System...
server # [   33.648685] systemd[1]: Mounted FUSE Control File System.
server # [   34.078234] systemd[1]: Finished Load/Save OS Random Seed.
server # [   34.094546] systemd[1]: Reached target First Boot Complete.
server # [   34.447267] systemd[1]: Finished Apply Kernel Variables.
server # [   34.578340] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
server # [   34.640725] systemd[1]: Starting Create Static Device Nodes in /dev...
server # [   35.431142] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.
server # [   36.174731] systemd[1]: Finished Create Static Device Nodes in /dev.
server # [   36.202091] systemd[1]: Reached target Preparation for Local File Systems.
server # [   36.264696] systemd[1]: Mounting /run/wrappers...
server # [   36.313570] systemd[1]: Starting Rule-based Manager for Device Events and Files...
server # [   36.788543] systemd[1]: Mounted /run/wrappers.
server # [   36.799060] systemd[1]: Reached target Local File Systems.
server # [   36.828051] systemd[1]: Listening on Boot Entries Service Socket.
server # [   36.903325] systemd[1]: Starting Create SUID/SGID Wrappers...
server # [   36.915054] systemd[1]: Update Boot Loader Random Seed was skipped because no trigger condition checks were met.
server # [   36.981153] systemd[1]: Starting Save Transient machine-id to Disk...
server # [   37.250835] systemd[1]: Started Journal Service.
server # [   37.293925] systemd-modules-load[375]: Module 'atkbd' is built in
server # [   37.315793] systemd-modules-load[375]: Module 'loop' is built in
server # [   37.406910] systemd-oomd[376]: No swap; memory pressure usage will be degraded
server # [   37.456309] systemd[1]: Starting Flush Journal to Persistent Storage...
server # [   38.165191] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
server # [   38.257923] systemd[1]: Finished Save Transient machine-id to Disk.
server # [   38.564160] systemd-journald[374]: Received client request to flush runtime journal.
server # [   39.108173] systemd-udevd[405]: Using default interface naming scheme 'v258'.
server # [   39.164112] systemd[1]: Finished Flush Journal to Persistent Storage.
server # [   39.205867] systemd[1]: Starting Create System Files and Directories...
server # [   41.946579] systemd[1]: Finished Create System Files and Directories.
server # [   42.004983] systemd[1]: Starting Rebuild Journal Catalog...
server # [   42.067322] systemd[1]: Starting Record System Boot/Shutdown in UTMP...
server # [   42.581569] systemd[1]: Started Rule-based Manager for Device Events and Files.
server # [   43.235336] systemd[1]: Finished Record System Boot/Shutdown in UTMP.
server # [   44.588378] systemd[1]: Finished Rebuild Journal Catalog.
server # [   44.632985] systemd[1]: Starting Update is Completed...
server # [   45.660274] systemd[1]: Finished Update is Completed.
server # [   48.774885] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.
server # [   48.801482] systemd[1]: Finished Create SUID/SGID Wrappers.
server # [   48.807363] systemd[1]: suid-sgid-wrappers.service: Consumed 1.689s CPU time, 5.5M memory peak.
server # [   50.766696] systemd[1]: Finished Firewall.
server # [   54.103012] systemd[1]: Finished Coldplug All udev Devices.
server # [   54.112246] systemd[1]: Reached target System Initialization.
server # [   54.123561] systemd[1]: Started Discard unused filesystem blocks once a week.
server # [   54.129400] systemd[1]: Started Daily Cleanup of Temporary Directories.
server # [   54.137609] systemd[1]: Reached target Timer Units.
server # [   54.149638] systemd[1]: Listening on D-Bus System Message Bus Socket.
server # [   54.150875] systemd[1]: Listening on Nix Daemon Socket.
server # [   54.151874] systemd[1]: Listening on Hostname Service Socket.
server # [   54.154888] systemd[1]: Reached target Socket Units.
server # [   54.184867] systemd[1]: Reached target Basic System.
server # [   54.190298] systemd[1]: Starting Import lastlog data into lastlog2 database...
server # [   54.217005] systemd[1]: Starting Name Service Cache Daemon (nsncd)...
server # [   54.270275] systemd[1]: Starting postgresql.service...
server # [   54.330259] systemd[1]: Started Reset console on configuration changes.
server # [   54.393085] systemd[1]: Starting resolvconf update...
server # [   54.443801] systemd[1]: Starting D-Bus System Message Bus...
server # [   55.955113] systemd[1]: Finished Import lastlog data into lastlog2 database.
server # [   56.213486] runuser[621]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)
server # [   56.488727] systemd[1]: Started Name Service Cache Daemon (nsncd).
server # [   56.510787] systemd[1]: Reached target Host and Network Name Lookups.
server # [   56.529821] systemd[1]: Reached target User and Group Name Lookups.
server # [   56.556265] nsncd[610]: Oct 26 13:08:16.409 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
server # [   56.598989] systemd[1]: Starting User Login Management...
server # [   57.118573] dbus-daemon[614]: dbus[614]: Unknown username "systemd-timesync" in message bus configuration file
server # [   57.767570] systemd[1]: Started D-Bus System Message Bus.
server # [   58.653734] systemd[1]: Stopped target Host and Network Name Lookups.
server # [   58.668152] systemd[1]: Stopping Host and Network Name Lookups...
server # [   58.716455] systemd[1]: Stopped target User and Group Name Lookups.
server # [   58.723952] systemd[1]: Stopping User and Group Name Lookups...
server # [   58.739318] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...
server # [   58.763865] systemd[1]: nscd.service: Deactivated successfully.
server # [   58.827147] systemd[1]: Stopped Name Service Cache Daemon (nsncd).
server # [   58.910775] systemd[1]: Starting Name Service Cache Daemon (nsncd)...
server # [   59.507280] systemd-logind[629]: New seat seat0.
server # [   59.593468] systemd[1]: Started User Login Management.
server # [   59.645892] systemd[1]: Starting linger-users.service...
server: Guest root shell did not produce any data yet...
server:   To debug, enter the VM and run 'systemctl status backdoor.service'.
server # [   59.937288] init-old[623]: The files belonging to this database system will be owned by user "postgres".
server # [   59.966428] init-old[623]: This user must also own the server process.
server # [   60.109389] systemd[1]: Started Name Service Cache Daemon (nsncd).
server # [   60.137863] systemd[1]: Reached target Host and Network Name Lookups.
server # [   60.154704] init-old[623]: The database cluster will be initialized with locale "C".
server # [   60.177667] init-old[623]: The default text search configuration will be set to "english".
server # [   60.187007] init-old[623]: Data page checksums are disabled.
server # [   60.195743] init-old[623]: fixing permissions on existing directory /var/lib/postgresql/data ... ok
server # [   60.245467] nsncd[674]: Oct 26 13:08:20.077 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
server # [   60.259286] systemd[1]: Reached target User and Group Name Lookups.
server # [   60.274605] init-old[623]: creating subdirectories ... ok
server # [   60.286835] init-old[623]: selecting dynamic shared memory implementation ... posix
server # [   60.471784] systemd[1]: linger-users.service: Deactivated successfully.
server # [   60.483103] systemd[1]: Finished linger-users.service.
server # [   61.022003] systemd[1]: Finished resolvconf update.
server # [   61.057581] systemd[1]: Reached target Preparation for Network.
server # [   61.106650] systemd[1]: Starting DHCP Client...
server # [   61.996638] init-old[623]: selecting default max_connections ... 100
server # [   62.967173] init-old[623]: selecting default shared_buffers ... 128MB
server # [   64.183359] dhcpcd[713]: dhcpcd-10.2.4 starting
server # [   64.486747] dhcpcd[729]: dev: loaded udev
server # [   64.936838] 8021q: 802.1Q VLAN Support v1.8
server # [   65.554889] cfg80211: Loading compiled-in X.509 certificates for regulatory database
server # [   65.785800] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
server # [   65.789936] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'
server # [   65.814985] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
server # [   65.818028] cfg80211: failed to load regulatory.db
server # [   66.829880] 8021q: adding VLAN 0 to HW filter on device eth0
server # [   66.783463] dhcpcd[729]: eth0: waiting for carrier
server # [   66.798648] dhcpcd[729]: eth0: carrier acquired
server # [   67.008387] dhcpcd[729]: DUID 00:01:00:01:32:72:0d:4a:52:54:00:12:34:56
server # [   67.015411] dhcpcd[729]: eth0: IAID 00:12:34:56
server # [   67.019372] dhcpcd[729]: eth0: adding address fe80::5054:ff:fe12:3456
server # [   67.360854] dhcpcd[729]: eth0: soliciting a DHCP lease
server # [   67.409936] dhcpcd[729]: eth0: offered 10.0.2.15 from 10.0.2.2
server # [   67.429345] dhcpcd[729]: eth0: probing address 10.0.2.15/24
server # [   68.597680] dhcpcd[729]: eth0: soliciting an IPv6 router
server # [   68.616676] dhcpcd[729]: eth0: Router Advertisement from fe80::2
server # [   68.629915] dhcpcd[729]: eth0: adding address fec0::5054:ff:fe12:3456/64
server # [   68.647900] dhcpcd[729]: eth0: adding route to fec0::/64
server # [   68.663020] dhcpcd[729]: eth0: adding default route via fe80::2
server # [   72.525059] dhcpcd[729]: eth0: leased 10.0.2.15 for 86400 seconds
server # [   72.534708] dhcpcd[729]: eth0: adding route to 10.0.2.0/24
server # [   72.542194] dhcpcd[729]: eth0: adding default route via 10.0.2.2
server # [   73.584031] init-old[623]: selecting default time zone ... UTC
server # [   73.641524] init-old[623]: creating configuration files ... ok
server # [   75.598155] systemd[1]: Started DHCP Client.
server # [   78.983854] init-old[623]: running bootstrap script ... ok
server # [   81.173372] systemd[1]: Found device /dev/hvc0.
server # [   81.875931] systemd[1]: Found device /dev/ttyAMA0.
server # [   81.929191] systemd[1]: Started backdoor.service.
server # connecting to host...
server # [   82.938319] (udev-worker)[879]: Network interface NamePolicy= disabled on kernel command line.
server: Guest shell says: b'Spawning backdoor root shell...\n'
server: connected to guest root shell
server: (connecting took 83.42 seconds)
server: (finished: waiting for the VM to finish booting, in 83.42 seconds)
server # [   84.123978] dhcpcd[729]: eth0: IAID 00:12:34:56
server # [   84.202914] dhcpcd[729]: eth0: soliciting an IPv6 router
server # [   85.038148] dhcpcd[729]: eth0: rebinding lease of 10.0.2.15
server # [   85.061242] dhcpcd[729]: eth0: leased 10.0.2.15 for 86400 seconds
server # [   87.405712] (udev-worker)[922]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.
server # [   87.438656] (udev-worker)[922]: Network interface NamePolicy= disabled on kernel command line.
server # [   89.222358] systemd[1]: Found device Virtio network device.
server # [   89.248821] systemd[1]: Starting Address configuration of eth1...
server # [   90.466656] 8021q: adding VLAN 0 to HW filter on device eth1
server # [   90.653907] network-addresses-eth1-start[943]: adding address 192.168.1.1/24... done
server # [   90.826912] network-addresses-eth1-start[943]: adding address 2001:db8:1::1/64... done
server # [   91.138528] systemd[1]: Finished Address configuration of eth1.
server # [   91.169053] systemd[1]: Starting Networking Setup...
server # [   94.127325] systemd[1]: Finished Networking Setup.
server # [   94.151376] systemd[1]: Reached target Network.
server # [   94.193010] systemd[1]: Starting Permit User Sessions...
server # [   95.026359] systemd[1]: Finished Permit User Sessions.
server # [   95.096380] systemd[1]: Started Getty on tty1.
server # [   95.097564] systemd[1]: Reached target Login Prompts.
server # [  101.499672] init-old[623]: performing post-bootstrap initialization ... ok
server # [  105.500131] init-old[623]: syncing data to disk ... ok
server # [  105.509678] init-old[623]: initdb: warning: enabling "trust" authentication for local connections
server # [  105.510211] 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.
server # [  105.511078] init-old[623]: Success. You can now start the database server using:
server # [  105.511534] init-old[623]:     /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-postgresql-and-plugins-15.19/bin/pg_ctl -D /var/lib/postgresql/data -l logfile start
server # [  105.547021] runuser[621]: pam_unix(runuser:session): session closed for user postgres
server # [  105.746731] systemd-logind[629]: Watching system buttons on /dev/input/event0 (gpio-keys)
server # [  106.627208] postgres[1103]: 2026-10-26 13:09:06.603 UTC [1103] LOG:  starting PostgreSQL 15.19 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 15.2.0, 64-bit
server # [  106.773781] postgres[1103]: 2026-10-26 13:09:06.755 UTC [1103] LOG:  listening on IPv6 address "::1", port 5432
server # [  106.785487] postgres[1103]: 2026-10-26 13:09:06.767 UTC [1103] LOG:  listening on IPv4 address "127.0.0.1", port 5432
server # [  106.799548] postgres[1103]: 2026-10-26 13:09:06.781 UTC [1103] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
server # [  106.900008] postgres[1110]: 2026-10-26 13:09:06.880 UTC [1110] LOG:  database system was shut down at 2026-10-26 13:09:01 UTC
server # [  107.013814] postgres[1103]: 2026-10-26 13:09:06.996 UTC [1103] LOG:  database system is ready to accept connections
server # [  107.078129] systemd[1]: Started postgresql.service.
server # [  107.079534] systemd[1]: Reached target Multi-User System.
server # [  107.092133] systemd[1]: Startup finished in 18.795s (kernel) + 1min 28.277s (userspace) = 1min 47.073s.
server: (finished: waiting for unit postgresql.service, in 108.59 seconds)
subtest: Seed the source cluster
server: must succeed: /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-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"
server # [  108.739243] mousedev: PS/2 mouse device common for all mice
server # [  111.603438] systemd-logind[629]: Watching system buttons on /dev/input/event1 (QEMU QEMU USB Keyboard)
server: (finished: must succeed: /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-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.21 seconds)
server: must succeed: /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-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"
server: (finished: must succeed: /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-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 1.87 seconds)
(finished: subtest: Seed the source cluster, in 14.08 seconds)
subtest: Control: with no guard the start loop brings the source up
server: must succeed: systemctl stop postgresql
server # [  122.666970] systemd[1]: Stopping postgresql.service...
server # [  122.721970] postgres[1103]: 2026-10-26 13:09:22.633 UTC [1103] LOG:  received fast shutdown request
server # [  122.722899] postgres[1103]: 2026-10-26 13:09:22.670 UTC [1103] LOG:  aborting any active transactions
server # [  122.853077] postgres[1103]: 2026-10-26 13:09:22.827 UTC [1103] LOG:  background worker "logical replication launcher" (PID 1113) exited with exit code 1
server # [  122.889748] postgres[1108]: 2026-10-26 13:09:22.857 UTC [1108] LOG:  shutting down
server # [  122.893488] postgres[1108]: 2026-10-26 13:09:22.876 UTC [1108] LOG:  checkpoint starting: shutdown immediate
server # [  123.629271] postgres[1108]: 2026-10-26 13:09:23.606 UTC [1108] LOG:  checkpoint complete: wrote 2176 buffers (13.3%); 0 WAL file(s) added, 0 removed, 4 recycled; write=0.381 s, sync=0.232 s, total=0.742 s; sync files=28, longest=0.177 s, average=0.009 s; distance=69073 kB, estimate=69073 kB
server # [  123.739968] postgres[1103]: 2026-10-26 13:09:23.718 UTC [1103] LOG:  database system is shut down
server # [  123.802740] systemd[1]: postgresql.service: Deactivated successfully.
server # [  123.821052] systemd[1]: Stopped postgresql.service.
server # [  123.822413] systemd[1]: postgresql.service: Consumed 19.581s CPU time, 233.3M memory peak, 241.1M written to disk, 1.2K incoming IP traffic, 1.8K outgoing IP traffic.
server: (finished: must succeed: systemctl stop postgresql, in 1.62 seconds)
server: must succeed: systemd-run --unit=salt-sim --collect /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive salt_sim
server # [  124.478017] systemd[1]: Started [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive salt_sim.
server # Running as unit: salt-sim.service; invocation ID: 9065dfacaf5043b3a7d57b23eb102230
server: (finished: must succeed: systemd-run --unit=salt-sim --collect /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive salt_sim, in 0.72 seconds)
server: waiting for success: systemctl is-active --quiet postgresql
server # [  125.348401] systemd[1]: Starting postgresql.service...
server # [  126.493583] postgres[1241]: 2026-10-26 13:09:26.461 UTC [1241] LOG:  starting PostgreSQL 15.19 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 15.2.0, 64-bit
server # [  126.506302] postgres[1241]: 2026-10-26 13:09:26.486 UTC [1241] LOG:  listening on IPv6 address "::1", port 5432
server # [  126.507308] postgres[1241]: 2026-10-26 13:09:26.486 UTC [1241] LOG:  listening on IPv4 address "127.0.0.1", port 5432
server # [  126.525835] postgres[1241]: 2026-10-26 13:09:26.505 UTC [1241] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
server # [  126.627289] postgres[1255]: 2026-10-26 13:09:26.605 UTC [1255] LOG:  database system was shut down at 2026-10-26 13:09:23 UTC
server # [  126.800078] postgres[1241]: 2026-10-26 13:09:26.780 UTC [1241] LOG:  database system is ready to accept connections
server # [  126.835307] systemd[1]: Started postgresql.service.
server: (finished: waiting for success: systemctl is-active --quiet postgresql, in 2.76 seconds)
server: must succeed: systemctl stop salt-sim
server # [  128.107642] systemd[1]: Stopping [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive salt_sim...
server # [  128.201363] systemd[1]: salt-sim.service: Deactivated successfully.
server # [  128.213990] systemd[1]: Stopped [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive salt_sim.
server: (finished: must succeed: systemctl stop salt-sim, in 0.94 seconds)
(finished: subtest: Control: with no guard the start loop brings the source up, in 6.05 seconds)
subtest: A systemd start is refused while the block is held
server: must succeed: systemd-run --unit=hold-block --collect /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive hold_block
server # [  128.891228] systemd[1]: Started [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive hold_block.
server # Running as unit: hold-block.service; invocation ID: 9d6cdbc3f37245e584c355d9541a75df
server: (finished: must succeed: systemd-run --unit=hold-block --collect /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive hold_block, in 0.69 seconds)
server: waiting for success: systemctl show -p ExecCondition postgresql | grep -q start-guard
server # [  129.547131] systemd[1]: Stopping postgresql.service...
server # [  129.599275] postgres[1241]: 2026-10-26 13:09:29.526 UTC [1241] LOG:  received fast shutdown request
server # [  129.600163] postgres[1241]: 2026-10-26 13:09:29.546 UTC [1241] LOG:  aborting any active transactions
server # [  129.749832] postgres[1241]: 2026-10-26 13:09:29.728 UTC [1241] LOG:  background worker "logical replication launcher" (PID 1259) exited with exit code 1
server # [  129.778045] postgres[1251]: 2026-10-26 13:09:29.735 UTC [1251] LOG:  shutting down
server # [  129.779232] postgres[1251]: 2026-10-26 13:09:29.753 UTC [1251] LOG:  checkpoint starting: shutdown immediate
server # [  129.869378] postgres[1251]: 2026-10-26 13:09:29.846 UTC [1251] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.025 s, sync=0.015 s, total=0.111 s; sync files=2, longest=0.011 s, average=0.008 s; distance=0 kB, estimate=0 kB
server # [  129.978287] postgres[1241]: 2026-10-26 13:09:29.954 UTC [1241] LOG:  database system is shut down
server # [  130.061595] systemd[1]: postgresql.service: Deactivated successfully.
server # [  130.085653] systemd[1]: Stopped postgresql.service.
server # [  130.512990] systemd[1]: Reload requested from client PID 1304 ('systemctl') (unit hold-block.service)...
server # [  130.514227] systemd[1]: Reloading...
server # [  135.823936] systemd[1]: Reloading finished in 5292 ms.
server: (finished: waiting for success: systemctl show -p ExecCondition postgresql | grep -q start-guard, in 7.48 seconds)
server: must fail: systemctl start postgresql
server # [  137.049440] systemd[1]: Starting postgresql.service...
server # [  137.615627] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  137.629572] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  137.638132] systemd[1]: Failed to start postgresql.service.
server # Job for postgresql.service failed because the control process exited with error code.
server # See "systemctl status postgresql.service" and "journalctl -xeu postgresql.service" for details.
server: (finished: must fail: systemctl start postgresql, in 1.24 seconds)
server: must succeed: sleep 5
server: (finished: must succeed: sleep 5, in 5.48 seconds)
server: must fail: systemctl is-active --quiet postgresql
server: (finished: must fail: systemctl is-active --quiet postgresql, in 0.45 seconds)
server: must succeed: systemctl show -p Restart postgresql
server: (finished: must succeed: systemctl show -p Restart postgresql, in 0.59 seconds)
(finished: subtest: A systemd start is refused while the block is held, in 15.93 seconds)
subtest: The block expires on its own when the holder is SIGKILLed
server: must succeed: systemctl kill -s KILL hold-block
server # [  144.728135] systemd[1]: hold-block.service: Sent signal SIGKILL to main process 1278 (sleep) on client request.
server # [  144.751653] systemd[1]: hold-block.service: Killed unit cgroup '/system.slice/hold-block.service' with SIGKILL on client request.
server # [  144.766266] systemd[1]: hold-block.service: Main process exited, code=killed, status=9/KILL
server # [  144.775747] systemd[1]: hold-block.service: Failed with result 'signal'.
server: (finished: must succeed: systemctl kill -s KILL hold-block, in 0.58 seconds)
server: waiting for failure: systemctl is-active --quiet hold-block
server: (finished: waiting for failure: systemctl is-active --quiet hold-block, in 0.68 seconds)
server: must succeed: systemctl start postgresql
server # [  145.980245] systemd[1]: Starting postgresql.service...
server # [  147.967040] postgres[1420]: 2026-10-26 13:09:47.942 UTC [1420] LOG:  starting PostgreSQL 15.19 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 15.2.0, 64-bit
server # [  147.986967] postgres[1420]: 2026-10-26 13:09:47.969 UTC [1420] LOG:  listening on IPv6 address "::1", port 5432
server # [  147.994254] postgres[1420]: 2026-10-26 13:09:47.972 UTC [1420] LOG:  listening on IPv4 address "127.0.0.1", port 5432
server # [  148.003986] postgres[1420]: 2026-10-26 13:09:47.986 UTC [1420] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
server # [  148.124118] postgres[1423]: 2026-10-26 13:09:48.097 UTC [1423] LOG:  database system was shut down at 2026-10-26 13:09:29 UTC
server # [  148.238713] postgres[1420]: 2026-10-26 13:09:48.220 UTC [1420] LOG:  database system is ready to accept connections
server # [  149.102592] systemd[1]: Reload requested from client PID 1435 ('systemctl') (unit postgresql.service)...
server # [  149.122054] systemd[1]: Reloading...
server # [  155.093998] systemd[1]: Reloading finished in 5967 ms.
server # [  155.434797] systemd[1]: Started postgresql.service.
server: (finished: must succeed: systemctl start postgresql, in 10.08 seconds)
server: waiting for unit postgresql.service
server: (finished: waiting for unit postgresql.service, in 0.90 seconds)
server: must fail: test -e /run/systemd/system/postgresql.service.d/pg-upgrade-lock.conf
server: (finished: must fail: test -e /run/systemd/system/postgresql.service.d/pg-upgrade-lock.conf, in 0.34 seconds)
server: must succeed: systemctl show -p Restart postgresql
server: (finished: must succeed: systemctl show -p Restart postgresql, in 0.54 seconds)
server: must succeed: systemctl show -p NeedDaemonReload postgresql
server: (finished: must succeed: systemctl show -p NeedDaemonReload postgresql, in 0.56 seconds)
(finished: subtest: The block expires on its own when the holder is SIGKILLed, in 13.67 seconds)
subtest: The pid lock stops a direct start once the new cluster is up
server: must succeed: systemctl stop postgresql
server # [  158.415561] postgres[1420]: 2026-10-26 13:09:58.390 UTC [1420] LOG:  received fast shutdown request
server # [  158.465799] systemd[1]: Stopping postgresql.service...
server # [  158.467168] postgres[1420]: 2026-10-26 13:09:58.416 UTC [1420] LOG:  aborting any active transactions
server # [  158.613412] postgres[1420]: 2026-10-26 13:09:58.593 UTC [1420] LOG:  background worker "logical replication launcher" (PID 1426) exited with exit code 1
server # [  158.637802] postgres[1421]: 2026-10-26 13:09:58.605 UTC [1421] LOG:  shutting down
server # [  158.644814] postgres[1421]: 2026-10-26 13:09:58.626 UTC [1421] LOG:  checkpoint starting: shutdown immediate
server # [  158.752988] postgres[1421]: 2026-10-26 13:09:58.733 UTC [1421] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.043 s, sync=0.007 s, total=0.126 s; sync files=2, longest=0.004 s, average=0.004 s; distance=0 kB, estimate=0 kB
server # [  158.817009] postgres[1420]: 2026-10-26 13:09:58.795 UTC [1420] LOG:  database system is shut down
server # [  158.875207] systemd[1]: postgresql.service: Deactivated successfully.
server # [  158.886257] systemd[1]: Stopped postgresql.service.
server: (finished: must succeed: systemctl stop postgresql, in 1.07 seconds)
server: must succeed: systemd-run --unit=hold-lock --collect /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive hold_lock
server # [  159.451546] systemd[1]: Started [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive hold_lock.
server # Running as unit: hold-lock.service; invocation ID: d1076a9bcb9a42ccaf1b469c3842c035
server: (finished: must succeed: systemd-run --unit=hold-lock --collect /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive hold_lock, in 0.58 seconds)
server: waiting for success: test -s /var/lib/postgresql/data/postmaster.pid
server # [  160.346636] runuser[1517]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)
server: (finished: waiting for success: test -s /var/lib/postgresql/data/postmaster.pid, in 2.16 seconds)
server: must fail: runuser -u postgres -- /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-postgresql-and-plugins-15.19/bin/pg_ctl start -D /var/lib/postgresql/data -w -s -l /tmp/pg_ctl.log -t 5
server # [  161.837388] drive[1518]: [13:10:01] Locked /var/lib/postgresql/data with pg_upgrade pid 1521
server # [  162.187944] runuser[1536]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)
server # pg_ctl: another server might be running; trying to start server anyway
server # pg_ctl: could not start server
server # Examine the log output.
server # [  163.400813] runuser[1536]: pam_unix(runuser:session): session closed for user postgres
server: (finished: must fail: runuser -u postgres -- /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-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.70 seconds)
server: must succeed: systemctl kill -s KILL hold-lock
server # [  163.922502] systemd[1]: hold-lock.service: Sent signal SIGKILL to main process 1511 (drive) on client request.
server # [  163.941756] systemd[1]: hold-lock.service: Killed unit cgroup '/system.slice/hold-lock.service' with SIGKILL on client request.
server # [  163.995373] systemd[1]: hold-lock.service: Main process exited, code=killed, status=9/KILL
server # [  164.037624] systemd[1]: hold-lock.service: Failed with result 'signal'.
server: (finished: must succeed: systemctl kill -s KILL hold-lock, in 0.62 seconds)
server: waiting for failure: systemctl is-active --quiet hold-lock
server: (finished: waiting for failure: systemctl is-active --quiet hold-lock, in 0.70 seconds)
server: must succeed: runuser -u postgres -- /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-postgresql-and-plugins-15.19/bin/pg_ctl start -D /var/lib/postgresql/data -w -s -l /tmp/pg_ctl.log 
server # [  165.215526] runuser[1565]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)
server # pg_ctl: another server might be running; trying to start server anyway
server # [  166.835257] runuser[1565]: pam_unix(runuser:session): session closed for user postgres
server: (finished: must succeed: runuser -u postgres -- /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-postgresql-and-plugins-15.19/bin/pg_ctl start -D /var/lib/postgresql/data -w -s -l /tmp/pg_ctl.log , in 2.11 seconds)
server: must succeed: runuser -u postgres -- /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-postgresql-and-plugins-15.19/bin/pg_ctl stop -D /var/lib/postgresql/data -w -s  
server # [  167.326658] runuser[1592]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)
server # [  167.749947] runuser[1592]: pam_unix(runuser:session): session closed for user postgres
server: (finished: must succeed: runuser -u postgres -- /nix/store/pi0h02x85f8iisji4nfv287jky9c1cl5-postgresql-and-plugins-15.19/bin/pg_ctl stop -D /var/lib/postgresql/data -w -s  , in 0.96 seconds)
server: must succeed: rm -f /run/pg-upgrade-source.pid
server: (finished: must succeed: rm -f /run/pg-upgrade-source.pid, in 0.35 seconds)
server: must succeed: systemctl start postgresql
server # [  168.674854] systemd[1]: Starting postgresql.service...
server # [  170.084315] postgres[1620]: 2026-10-26 13:10:10.057 UTC [1620] LOG:  starting PostgreSQL 15.19 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 15.2.0, 64-bit
server # [  170.105347] postgres[1620]: 2026-10-26 13:10:10.087 UTC [1620] LOG:  listening on IPv6 address "::1", port 5432
server # [  170.109646] postgres[1620]: 2026-10-26 13:10:10.090 UTC [1620] LOG:  listening on IPv4 address "127.0.0.1", port 5432
server # [  170.127707] postgres[1620]: 2026-10-26 13:10:10.107 UTC [1620] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
server # [  170.236026] postgres[1623]: 2026-10-26 13:10:10.213 UTC [1623] LOG:  database system was shut down at 2026-10-26 13:10:07 UTC
server # [  170.371190] postgres[1620]: 2026-10-26 13:10:10.351 UTC [1620] LOG:  database system is ready to accept connections
server # [  170.411597] systemd[1]: Started postgresql.service.
server: (finished: must succeed: systemctl start postgresql, in 2.35 seconds)
server: waiting for unit postgresql.service
server: (finished: waiting for unit postgresql.service, in 0.73 seconds)
(finished: subtest: The pid lock stops a direct start once the new cluster is up, in 13.33 seconds)
subtest: A real pg_upgrade copy under a start storm
server: must succeed: systemd-run --unit=fake-initiate --collect --pipe --wait /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive upgrade
server # [  171.794123] systemd[1]: Started [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive upgrade.
server # Running as unit: fake-initiate.service; invocation ID: 77d4be16f60a4ac49082794d37009230
server # [  172.464507] systemd[1]: Stopping postgresql.service...
server # [  172.501774] postgres[1620]: 2026-10-26 13:10:12.441 UTC [1620] LOG:  received fast shutdown request
server # [  172.502841] postgres[1620]: 2026-10-26 13:10:12.474 UTC [1620] LOG:  aborting any active transactions
server # [  172.625604] postgres[1620]: 2026-10-26 13:10:12.606 UTC [1620] LOG:  background worker "logical replication launcher" (PID 1626) exited with exit code 1
server # [  172.641834] postgres[1621]: 2026-10-26 13:10:12.606 UTC [1621] LOG:  shutting down
server # [  172.647511] postgres[1621]: 2026-10-26 13:10:12.626 UTC [1621] LOG:  checkpoint starting: shutdown immediate
server # [  172.728588] postgres[1621]: 2026-10-26 13:10:12.711 UTC [1621] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.031 s, sync=0.008 s, total=0.105 s; sync files=2, longest=0.005 s, average=0.004 s; distance=0 kB, estimate=0 kB
server # [  172.797491] postgres[1620]: 2026-10-26 13:10:12.780 UTC [1620] LOG:  database system is shut down
server # [  172.867584] systemd[1]: postgresql.service: Deactivated successfully.
server # [  172.876939] systemd[1]: Stopped postgresql.service.
server # [  173.378242] systemd[1]: Reload requested from client PID 1658 ('systemctl') (unit fake-initiate.service)...
server # [  173.391672] systemd[1]: Reloading...
server # [  178.879250] systemd[1]: Reloading finished in 5480 ms.
server # [  179.459170] runuser[1688]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)
server # [  186.983023] input: QEMU Virtio Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:08.0/virtio7/input/input3
server # [  203.756174] systemd[1]: Starting Virtual Console Setup...
server # [  204.106640] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.
server # [  204.108279] systemd[1]: Stopped Virtual Console Setup.
server # [  204.178256] systemd[1]: Starting Virtual Console Setup...
server # [  209.512890] systemd[1]: Finished Virtual Console Setup.
server # [  212.118871] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
server # [  213.210533] systemd-logind[629]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)
server # initdb: warning: enabling "trust" authentication for local connections
server # 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.
server # [  215.771082] runuser[1688]: pam_unix(runuser:session): session closed for user postgres
server # [  216.011037] systemd[1]: Started [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive salt_sim.
server # Running as unit: salt-sim.service; invocation ID: 1d193074f6ae41ee830ca1f022face39
server # [  216.355521] runuser[1836]: pam_unix(runuser:session): session opened for user postgres(uid=997) by (uid=0)
server # [  216.627604] systemd[1]: Starting postgresql.service...
server # [  217.103977] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  217.130152] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  217.131379] systemd[1]: Failed to start postgresql.service.
server # [  217.881913] systemd[1]: Starting postgresql.service...
server # [  218.419809] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  218.457585] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  218.458487] systemd[1]: Failed to start postgresql.service.
server # [  219.179486] systemd[1]: Starting postgresql.service...
server # [  219.743696] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  219.770361] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  219.771209] systemd[1]: Failed to start postgresql.service.
server # [  220.513709] systemd[1]: Starting postgresql.service...
server # [  221.042264] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  221.043876] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  221.065848] systemd[1]: Failed to start postgresql.service.
server # [  221.799367] systemd[1]: Starting postgresql.service...
server # [  222.346649] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  222.348047] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  222.377811] systemd[1]: Failed to start postgresql.service.
server # [  223.008277] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  223.015126] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  223.037855] systemd[1]: Failed to start postgresql.service.
server # [  223.715682] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  223.735300] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  223.756795] systemd[1]: Failed to start postgresql.service.
server # [  224.417890] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  224.418923] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  224.419379] systemd[1]: Failed to start postgresql.service.
server # [  225.171023] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  225.190139] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  225.190886] systemd[1]: Failed to start postgresql.service.
server # [  225.833702] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  225.835554] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  225.854200] systemd[1]: Failed to start postgresql.service.
server # [  226.490277] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  226.492089] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  226.505033] systemd[1]: Failed to start postgresql.service.
server # [  227.153288] systemd[1]: Starting postgresql.service...
server # [  227.600917] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  227.640191] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  227.650515] systemd[1]: Failed to start postgresql.service.
server # [  228.281150] systemd[1]: Starting postgresql.service...
server # [  228.762116] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  228.763479] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  228.798624] systemd[1]: Failed to start postgresql.service.
server # [  229.411102] systemd[1]: Starting postgresql.service...
server # [  229.854252] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  229.855284] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  229.881982] systemd[1]: Failed to start postgresql.service.
server # [  230.495117] systemd[1]: Starting postgresql.service...
server # [  230.934974] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  230.964894] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  230.965998] systemd[1]: Failed to start postgresql.service.
server # [  231.634364] systemd[1]: Starting postgresql.service...
server # [  232.193648] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  232.195293] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  232.217423] systemd[1]: Failed to start postgresql.service.
server # [  232.903099] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  232.906203] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  232.906916] systemd[1]: Failed to start postgresql.service.
server # [  233.554541] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  233.577921] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  233.578849] systemd[1]: Failed to start postgresql.service.
server # [  234.173020] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  234.183065] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  234.184068] systemd[1]: Failed to start postgresql.service.
server # [  234.849301] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  234.869088] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  234.870048] systemd[1]: Failed to start postgresql.service.
server # [  235.461022] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  235.462378] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  235.463200] systemd[1]: Failed to start postgresql.service.
server # [  236.131814] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  236.161207] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  236.162058] systemd[1]: Failed to start postgresql.service.
server # [  236.745428] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  236.746710] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  236.747540] systemd[1]: Failed to start postgresql.service.
server # [  237.387830] systemd[1]: Starting postgresql.service...
server # [  237.821056] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  237.826694] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  237.857631] systemd[1]: Failed to start postgresql.service.
server # [  238.528769] systemd[1]: Starting postgresql.service...
server # [  239.034329] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  239.035948] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  239.060177] systemd[1]: Failed to start postgresql.service.
server # [  239.776733] systemd[1]: Starting postgresql.service...
server # [  240.273388] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  240.279558] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  240.306546] systemd[1]: Failed to start postgresql.service.
server # [  241.010714] systemd[1]: Starting postgresql.service...
server # [  241.437707] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  241.439207] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  241.461931] systemd[1]: Failed to start postgresql.service.
server # [  242.134749] systemd[1]: Starting postgresql.service...
server # [  242.607969] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  242.616330] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  242.633807] systemd[1]: Failed to start postgresql.service.
server # [  243.293567] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  243.296393] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  243.310033] systemd[1]: Failed to start postgresql.service.
server # [  243.865673] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  243.866845] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  243.867566] systemd[1]: Failed to start postgresql.service.
server # [  244.501831] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  244.509317] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  244.510166] systemd[1]: Failed to start postgresql.service.
server # [  245.097639] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  245.098813] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  245.099526] systemd[1]: Failed to start postgresql.service.
server # [  245.706119] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  245.707371] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  245.708029] systemd[1]: Failed to start postgresql.service.
server # [  246.318140] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  246.319404] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  246.320251] systemd[1]: Failed to start postgresql.service.
server # [  246.920498] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  246.921597] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  246.944128] systemd[1]: Failed to start postgresql.service.
server # [  247.531366] systemd[1]: Starting postgresql.service...
server # [  248.130742] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  248.132140] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  248.174128] systemd[1]: Failed to start postgresql.service.
server # [  248.841232] systemd[1]: Starting postgresql.service...
server # [  249.300559] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  249.319294] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  249.320319] systemd[1]: Failed to start postgresql.service.
server # [  249.955240] systemd[1]: Starting postgresql.service...
server # [  250.380018] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  250.405869] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  250.406564] systemd[1]: Failed to start postgresql.service.
server # [  251.073541] systemd[1]: Starting postgresql.service...
server # [  251.622638] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  251.624005] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  251.654865] systemd[1]: Failed to start postgresql.service.
server # [  252.311973] systemd[1]: Starting postgresql.service...
server # [  252.846778] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  252.876144] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  252.878225] systemd[1]: Failed to start postgresql.service.
server # [  253.495215] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  253.501823] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  253.503476] systemd[1]: Failed to start postgresql.service.
server # [  254.163569] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  254.172202] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  254.190575] systemd[1]: Failed to start postgresql.service.
server # [  254.857321] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  254.861759] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  254.862415] systemd[1]: Failed to start postgresql.service.
server # [  255.575969] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  255.601818] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  255.602744] systemd[1]: Failed to start postgresql.service.
server # [  256.298053] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  256.309590] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  256.310375] systemd[1]: Failed to start postgresql.service.
server # [  256.915270] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  256.929025] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  256.930344] systemd[1]: Failed to start postgresql.service.
server # [  257.528359] systemd[1]: Starting postgresql.service...
server # [  257.963194] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  257.995836] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  258.002112] systemd[1]: Failed to start postgresql.service.
server # [  258.652023] systemd[1]: Starting postgresql.service...
server # [  259.083074] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  259.084230] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  259.113602] systemd[1]: Failed to start postgresql.service.
server # [  259.700776] systemd[1]: Starting postgresql.service...
server # [  260.111805] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  260.140191] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  260.143988] systemd[1]: Failed to start postgresql.service.
server # [  260.756176] systemd[1]: Starting postgresql.service...
server # [  261.223791] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  261.241620] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  261.255332] systemd[1]: Failed to start postgresql.service.
server # [  261.853054] systemd[1]: Starting postgresql.service...
server # [  262.314315] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  262.315822] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  262.341138] systemd[1]: Failed to start postgresql.service.
server # [  262.889624] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  262.890785] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  262.891481] systemd[1]: Failed to start postgresql.service.
server # [  263.530190] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  263.546493] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  263.547470] systemd[1]: Failed to start postgresql.service.
server # [  264.114278] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  264.115747] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  264.137646] systemd[1]: Failed to start postgresql.service.
server # [  264.723112] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  264.737992] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  264.739145] systemd[1]: Failed to start postgresql.service.
server # [  265.400777] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  265.414426] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  265.415874] systemd[1]: Failed to start postgresql.service.
server # [  266.095564] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  266.114462] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  266.115299] systemd[1]: Failed to start postgresql.service.
server # [  266.818733] systemd[1]: postgresql.service: Start request repeated too quickly.
server # [  266.822763] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  266.823584] systemd[1]: Failed to start postgresql.service.
server # [  267.670365] systemd[1]: Starting postgresql.service...
server # [  268.342772] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  268.357821] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  268.367699] systemd[1]: Failed to start postgresql.service.
server # [  269.102724] systemd[1]: Starting postgresql.service...
server # [  269.610181] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  269.611960] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  269.643776] systemd[1]: Failed to start postgresql.service.
server # [  270.251067] systemd[1]: Starting postgresql.service...
server # [  270.890875] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  270.898146] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  270.919860] systemd[1]: Failed to start postgresql.service.
server # [  271.918999] systemd[1]: Starting postgresql.service...
server # [  272.374488] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  272.386337] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  272.398711] systemd[1]: Failed to start postgresql.service.
server # [  272.892554] runuser[1836]: pam_unix(runuser:session): session closed for user postgres
server # [  273.132933] systemd[1]: Starting postgresql.service...
server # [  273.166632] systemd[1]: Stopping [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive salt_sim...
server # [  273.230709] systemd[1]: salt-sim.service: Deactivated successfully.
server # [  273.243114] systemd[1]: Stopped [systemd-run] /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive salt_sim.
server # [  273.259711] systemd[1]: salt-sim.service: Consumed 9.199s CPU time, 1.9M memory peak.
server # [  273.651964] systemd[1]: fake-initiate.service: Main process exited, code=exited, status=1/FAILURE
server # [  273.661780] systemd[1]: fake-initiate.service: Failed with result 'exit-code'.
server # [  273.667505] systemd[1]: fake-initiate.service: Consumed 36.154s CPU time, 148.3M memory peak, 238.2M written to disk.
server # [  273.690736] systemd[1]: postgresql.service: Condition check process exited, code=exited, status=255/EXCEPTION
server # [  273.701116] systemd[1]: postgresql.service: Failed with result 'exit-code'.
server # [  273.703832] systemd[1]: Failed to start postgresql.service.
server #           Finished with result: exit-code
server # Main processes terminated with: code=exited, status=1/FAILURE
server #                Service runtime: 1min 41.878s
server #              CPU time consumed: 36.154s
server #                    Memory peak: 148.3M (swap: 0B)
server #                       IO Bytes: written 238.2M
server: output: The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with locale "C".
The default text search configuration will be set to "english".

Data page checksums are disabled.

creating directory /var/lib/postgresql/data-17 ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default "max_connections" ... 100
selecting default "shared_buffers" ... 128MB
selecting default time zone ... UTC
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok
syncing data to disk ... ok


Success. You can now start the database server using:

    /nix/store/b93nnrxmkyz9mmh50hw0sn71rbmswp41-postgresql-and-plugins-17.11/bin/pg_ctl -D /var/lib/postgresql/data-17 -l logfile start

Performing Consistency Checks
-----------------------------
Checking cluster versions                                     ok
Checking database user is the install user                    ok
Checking database connection settings                         ok
Checking for prepared transactions                            ok
Checking for contrib/isn with bigint-passing mismatch         ok
Checking data type usage                                      ok
Checking for not-null constraint inconsistencies              ok
Creating dump of global objects                               ok
Creating dump of database schemas                             ok
[13:11:22] Locked /var/lib/postgresql/data with pg_upgrade pid 1839
Checking for presence of required libraries                   ok
Checking database user is the install user                    ok
Checking for prepared transactions                            ok
Checking for new cluster tablespace directories               ok

If pg_upgrade fails after this point, you must re-initdb the
new cluster before continuing.

Performing Upgrade
------------------
Setting locale and encoding for new cluster                   ok
Analyzing all rows in the new cluster                         ok
Freezing all rows in the new cluster                          ok
Deleting files from new pg_xact                               ok
Copying old pg_xact to new server                             ok
Setting oldest XID for new cluster                            ok
Setting next transaction ID and epoch for new cluster         ok
Deleting files from new pg_multixact/offsets                  ok
Copying old pg_multixact/offsets to new server                ok
Deleting files from new pg_multixact/members                  ok
Copying old pg_multixact/members to new server                ok
Setting next multixact ID and offset for new cluster          ok
Resetting WAL archives                                        ok
Setting frozenxid and minmxid counters in new cluster         ok
Restoring global objects in the new cluster                   ok
Restoring database schemas in the new cluster                 ok
Copying user relation files                                   ok
Setting next OID for new cluster                              ok
Sync data directory to disk                                   ok
Creating script to delete old cluster                         ok
Checking for extension updates                                ok

Upgrade Complete
----------------
Optimizer statistics are not transferred by pg_upgrade.
Once you start the new server, consider running:
    /nix/store/b93nnrxmkyz9mmh50hw0sn71rbmswp41-postgresql-and-plugins-17.11/bin/vacuumdb -U postgres --all --analyze-in-stages
Running this script will delete the old cluster's data files:
    ./delete_old_cluster.sh
[13:11:53] ERROR: postgresql.service is activating after pg_upgrade; the copied data files may be inconsistent

!!! Test "A real pg_upgrade copy under a start storm" failed with error: "command `systemd-run --unit=fake-initiate --collect --pipe --wait /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive upgrade` failed (exit code 1)"
!!! Traceback (most recent call last):
!!!   File "<string>", line 69, in <module>
!!!     server.succeed(f"systemd-run --unit=fake-initiate --collect --pipe --wait {DRIVE} upgrade")
!!! 
!!! RequestedAssertionFailed: command `systemd-run --unit=fake-initiate --collect --pipe --wait /nix/store/v7833w1jm7rl64gns1izka6rd90a333r-drive/bin/drive upgrade` failed (exit code 1)
cleanup
kill machine (pid 9)
qemu-system-aarch64: terminating on signal 15 from pid 6 (/nix/store/y88crn50yx35fiiwcjx6xqwi6ahk7mlq-python3-3.13.11/bin/python3.13)
vde_switch: EOF data port: Interrupted system call
kill vlan (pid 7)
(finished: cleanup, in 0.00 seconds)
vde_switch: Caught signal 15, cleaning up and exiting