nixbot

1these 12 derivations will be built:2  /nix/store/fhjdrlqgqjl60m89sj7fivjsfy6n2cla-unit-script-setup-git-repo-start.drv3  /nix/store/1zl3mqabyh667qxm369qksscg4gfvqj2-unit-setup-git-repo.service.drv4  /nix/store/3qm3lra5v35nibywjivk2m3wak12w1sw-system-units.drv5  /nix/store/9si2bgaqf4j0fc9jf05b5l4mcky9msya-etc.drv6  /nix/store/iasz431jzlvgqb6k3k85glsnzrnpj1j2-activate.drv7  /nix/store/bj1lgvwpqpy0f2dy586dixqxny9mv7s4-nixos-system-buildbot-test.drv8  /nix/store/6fn1k6barknci14rg3k38gk7zikq56z1-closure-info.drv9  /nix/store/ddhl204whv3qzbn1566cr08x7whxyk9s-run-nixos-vm.drv10  /nix/store/ni8c8blxdzahd235xi97jqsdhn7z1flf-nixos-vm.drv11  /nix/store/152vybr34vmfglgiklqasdjhza9ws2rg-driverConfiguration.json.drv12  /nix/store/s107k3wyvsjfqf6wvrq717aydgy1ss4l-nixos-test-driver-scheduled-effects.drv13  /nix/store/ncj0ghxz3kcdpsqd0379gbbmg4vk8515-vm-test-run-scheduled-effects.drv14building '/nix/store/fhjdrlqgqjl60m89sj7fivjsfy6n2cla-unit-script-setup-git-repo-start.drv'15building '/nix/store/1zl3mqabyh667qxm369qksscg4gfvqj2-unit-setup-git-repo.service.drv'16building '/nix/store/3qm3lra5v35nibywjivk2m3wak12w1sw-system-units.drv'17building '/nix/store/9si2bgaqf4j0fc9jf05b5l4mcky9msya-etc.drv'18building '/nix/store/iasz431jzlvgqb6k3k85glsnzrnpj1j2-activate.drv'19building '/nix/store/bj1lgvwpqpy0f2dy586dixqxny9mv7s4-nixos-system-buildbot-test.drv'20nixos-system-buildbot-test> structuredAttrs is enabled21building '/nix/store/6fn1k6barknci14rg3k38gk7zikq56z1-closure-info.drv'22closure-info> structuredAttrs is enabled23building '/nix/store/ddhl204whv3qzbn1566cr08x7whxyk9s-run-nixos-vm.drv'24building '/nix/store/ni8c8blxdzahd235xi97jqsdhn7z1flf-nixos-vm.drv'25building '/nix/store/152vybr34vmfglgiklqasdjhza9ws2rg-driverConfiguration.json.drv'26driverConfiguration.json> structuredAttrs is enabled27building '/nix/store/s107k3wyvsjfqf6wvrq717aydgy1ss4l-nixos-test-driver-scheduled-effects.drv'28nixos-test-driver-scheduled-effects> Running type check (enable/disable: config.skipTypeCheck)29nixos-test-driver-scheduled-effects> See https://nixos.org/manual/nixos/stable/#test-opt-skipTypeCheck30nixos-test-driver-scheduled-effects> All checks passed!31nixos-test-driver-scheduled-effects> Linting test script (enable/disable: config.skipLint)32nixos-test-driver-scheduled-effects> See https://nixos.org/manual/nixos/stable/#test-opt-skipLint33nixos-test-driver-scheduled-effects> All checks passed!34building '/nix/store/ncj0ghxz3kcdpsqd0379gbbmg4vk8515-vm-test-run-scheduled-effects.drv' on 'ssh-ng://nix@jamie'35building '/nix/store/ncj0ghxz3kcdpsqd0379gbbmg4vk8515-vm-test-run-scheduled-effects.drv'36vm-test-run-scheduled-effects> Machine state will be reset. To keep it, pass --keep-machine-state37vm-test-run-scheduled-effects> start all VLans38vm-test-run-scheduled-effects> (finished: start all VLans, in 0.01 seconds)39vm-test-run-scheduled-effects> Test will time out and terminate in 3600 seconds40vm-test-run-scheduled-effects> run the VM test script41vm-test-run-scheduled-effects> additionally exposed symbols:42vm-test-run-scheduled-effects>     buildbot,43vm-test-run-scheduled-effects>     vlan1,44vm-test-run-scheduled-effects>     start_all, test_script, machines, machines_qemu, machines_nspawn, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, BaseMachine, QemuMachine, NspawnMachine, t, debug, dump_machine_ssh45vm-test-run-scheduled-effects> buildbot: waiting for unit sshd.service46vm-test-run-scheduled-effects> buildbot: waiting for the VM to finish booting47vm-test-run-scheduled-effects> buildbot: starting vm48vm-test-run-scheduled-effects> buildbot: QEMU running (pid 12)49vm-test-run-scheduled-effects> buildbot # Disk image does not exist, creating the virtualisation disk image...50vm-test-run-scheduled-effects> buildbot # Formatting '/build/vm-state-buildbot/tmp.Vqd2IFYnM5', fmt=raw size=107374182451vm-test-run-scheduled-effects> buildbot # mke2fs 1.47.3 (8-Jul-2025)52vm-test-run-scheduled-effects> buildbot # Discarding device blocks:      0/262144             done53vm-test-run-scheduled-effects> buildbot # Creating filesystem with 262144 4k blocks and 65536 inodes54vm-test-run-scheduled-effects> buildbot # Filesystem UUID: c514fb58-d4de-4825-ac37-a7ca3e1ef2fb55vm-test-run-scheduled-effects> buildbot # Superblock backups stored on blocks:56vm-test-run-scheduled-effects> buildbot # 	32768, 98304, 163840, 22937657vm-test-run-scheduled-effects> buildbot # 58vm-test-run-scheduled-effects> buildbot # Allocating group tables: 0/8   done59vm-test-run-scheduled-effects> buildbot # Writing inode tables: 0/8   done60vm-test-run-scheduled-effects> buildbot # Creating journal (8192 blocks): done61vm-test-run-scheduled-effects> buildbot # Writing superblocks and filesystem accounting information: 0/8   done62vm-test-run-scheduled-effects> buildbot # 63vm-test-run-scheduled-effects> buildbot # Virtualisation disk image created.64vm-test-run-scheduled-effects> buildbot # SeaBIOS (version rel-1.17.0-0-gb52ca86e094d-prebuilt.qemu.org)65vm-test-run-scheduled-effects> buildbot # 66vm-test-run-scheduled-effects> buildbot # 67vm-test-run-scheduled-effects> buildbot # iPXE (http://ipxe.org) 00:03.0 CA00 PCI2.10 PnP PMM+3EFD1920+3EF31920 CA0068vm-test-run-scheduled-effects> buildbot # Press Ctrl-B to configure iPXE (PCI 00:03.0)...69vm-test-run-scheduled-effects> buildbot # 70vm-test-run-scheduled-effects> buildbot # 71vm-test-run-scheduled-effects> buildbot # 72vm-test-run-scheduled-effects> buildbot # 73vm-test-run-scheduled-effects> buildbot # iPXE (http://ipxe.org) 00:09.0 CB00 PCI2.10 PnP PMM 3EFD1920 3EF31920 CB0074vm-test-run-scheduled-effects> buildbot # Press Ctrl-B to configure iPXE (PCI 00:09.0)...75vm-test-run-scheduled-effects> buildbot # 76vm-test-run-scheduled-effects> buildbot # 77vm-test-run-scheduled-effects> buildbot # Booting from ROM...78vm-test-run-scheduled-effects> buildbot # Probing EDD (edd=off to disable)... ok[    0.000000] Linux version 6.18.36 (nixbld@localhost) (gcc (GCC) 15.2.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT_DYNAMIC Fri Jun 19 11:44:16 UTC 202679vm-test-run-scheduled-effects> buildbot # [    0.000000] Command line: console=ttyS0 console=tty0 panic=1 boot.panic_on_fail clocksource=acpi_pm root=fstab loglevel=7 net.ifnames=0 lsm=landlock,yama,bpf init=/nix/store/nswbpy9j7m34fi0s5bq3b34fk13smbw6-nixos-system-buildbot-test/init regInfo=/nix/store/p548j36n5rvkryzq8vgqxcwqpjb7m6i8-closure-info/registration console=ttyS0,115200n8 console=tty080vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-provided physical RAM map:81vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable82vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved83vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved84vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000003ffdafff] usable85vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-e820: [mem 0x000000003ffdb000-0x000000003fffffff] reserved86vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved87vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved88vm-test-run-scheduled-effects> buildbot # [    0.000000] BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved89vm-test-run-scheduled-effects> buildbot # [    0.000000] NX (Execute Disable) protection: active90vm-test-run-scheduled-effects> buildbot # [    0.000000] APIC: Static calls initialized91vm-test-run-scheduled-effects> buildbot # [    0.000000] SMBIOS 2.8 present.92vm-test-run-scheduled-effects> buildbot # [    0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.17.0-0-gb52ca86e094d-prebuilt.qemu.org 04/01/201493vm-test-run-scheduled-effects> buildbot # [    0.000000] DMI: Memory slots populated: 1/194vm-test-run-scheduled-effects> buildbot # [    0.000000] Hypervisor detected: KVM95vm-test-run-scheduled-effects> buildbot # [    0.000000] last_pfn = 0x3ffdb max_arch_pfn = 0x1000000000096vm-test-run-scheduled-effects> buildbot # [    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d0097vm-test-run-scheduled-effects> buildbot # [    0.000001] kvm-clock: using sched offset of 535488518 cycles98vm-test-run-scheduled-effects> buildbot # [    0.000002] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns99vm-test-run-scheduled-effects> buildbot # [    0.000005] tsc: Detected 2400.010 MHz processor100vm-test-run-scheduled-effects> buildbot # [    0.000813] last_pfn = 0x3ffdb max_arch_pfn = 0x10000000000101vm-test-run-scheduled-effects> buildbot # [    0.000850] MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs102vm-test-run-scheduled-effects> buildbot # [    0.000853] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT103vm-test-run-scheduled-effects> buildbot # [    0.002754] found SMP MP-table at [mem 0x000f5470-0x000f547f]104vm-test-run-scheduled-effects> buildbot # [    0.002765] Using GB pages for direct mapping105vm-test-run-scheduled-effects> buildbot # [    0.002851] RAMDISK: [mem 0x3e4ee000-0x3ffcffff]106vm-test-run-scheduled-effects> buildbot # [    0.002858] ACPI: Early table checksum verification disabled107vm-test-run-scheduled-effects> buildbot # [    0.002860] ACPI: RSDP 0x00000000000F5290 000014 (v00 BOCHS )108vm-test-run-scheduled-effects> buildbot # [    0.002864] ACPI: RSDT 0x000000003FFE23CC 000034 (v01 BOCHS  BXPC     00000001 BXPC 00000001)109vm-test-run-scheduled-effects> buildbot # [    0.002868] ACPI: FACP 0x000000003FFE2280 000074 (v01 BOCHS  BXPC     00000001 BXPC 00000001)110vm-test-run-scheduled-effects> buildbot # [    0.002874] ACPI: DSDT 0x000000003FFE0040 002240 (v01 BOCHS  BXPC     00000001 BXPC 00000001)111vm-test-run-scheduled-effects> buildbot # [    0.002876] ACPI: FACS 0x000000003FFE0000 000040112vm-test-run-scheduled-effects> buildbot # [    0.002878] ACPI: APIC 0x000000003FFE22F4 000078 (v03 BOCHS  BXPC     00000001 BXPC 00000001)113vm-test-run-scheduled-effects> buildbot # [    0.002880] ACPI: HPET 0x000000003FFE236C 000038 (v01 BOCHS  BXPC     00000001 BXPC 00000001)114vm-test-run-scheduled-effects> buildbot # [    0.002881] ACPI: WAET 0x000000003FFE23A4 000028 (v01 BOCHS  BXPC     00000001 BXPC 00000001)115vm-test-run-scheduled-effects> buildbot # [    0.002882] ACPI: Reserving FACP table memory at [mem 0x3ffe2280-0x3ffe22f3]116vm-test-run-scheduled-effects> buildbot # [    0.002884] ACPI: Reserving DSDT table memory at [mem 0x3ffe0040-0x3ffe227f]117vm-test-run-scheduled-effects> buildbot # [    0.002884] ACPI: Reserving FACS table memory at [mem 0x3ffe0000-0x3ffe003f]118vm-test-run-scheduled-effects> buildbot # [    0.002885] ACPI: Reserving APIC table memory at [mem 0x3ffe22f4-0x3ffe236b]119vm-test-run-scheduled-effects> buildbot # [    0.002885] ACPI: Reserving HPET table memory at [mem 0x3ffe236c-0x3ffe23a3]120vm-test-run-scheduled-effects> buildbot # [    0.002886] ACPI: Reserving WAET table memory at [mem 0x3ffe23a4-0x3ffe23cb]121vm-test-run-scheduled-effects> buildbot # [    0.003387] No NUMA configuration found122vm-test-run-scheduled-effects> buildbot # [    0.003389] Faking a node at [mem 0x0000000000000000-0x000000003ffdafff]123vm-test-run-scheduled-effects> buildbot # [    0.003392] NODE_DATA(0) allocated [mem 0x3ffd5780-0x3ffdacff]124vm-test-run-scheduled-effects> buildbot # [    0.005592] Zone ranges:125vm-test-run-scheduled-effects> buildbot # [    0.005593]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]126vm-test-run-scheduled-effects> buildbot # [    0.005595]   DMA32    [mem 0x0000000001000000-0x000000003ffdafff]127vm-test-run-scheduled-effects> buildbot # [    0.005596]   Normal   empty128vm-test-run-scheduled-effects> buildbot # [    0.005597]   Device   empty129vm-test-run-scheduled-effects> buildbot # [    0.005597] Movable zone start for each node130vm-test-run-scheduled-effects> buildbot # [    0.005598] Early memory node ranges131vm-test-run-scheduled-effects> buildbot # [    0.005598]   node   0: [mem 0x0000000000001000-0x000000000009efff]132vm-test-run-scheduled-effects> buildbot # [    0.005599]   node   0: [mem 0x0000000000100000-0x000000003ffdafff]133vm-test-run-scheduled-effects> buildbot # [    0.005600] Initmem setup node 0 [mem 0x0000000000001000-0x000000003ffdafff]134vm-test-run-scheduled-effects> buildbot # [    0.005657] On node 0, zone DMA: 1 pages in unavailable ranges135vm-test-run-scheduled-effects> buildbot # [    0.005922] On node 0, zone DMA: 97 pages in unavailable ranges136vm-test-run-scheduled-effects> buildbot # [    0.023142] On node 0, zone DMA32: 37 pages in unavailable ranges137vm-test-run-scheduled-effects> buildbot # [    0.024133] ACPI: PM-Timer IO Port: 0x608138vm-test-run-scheduled-effects> buildbot # [    0.024147] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])139vm-test-run-scheduled-effects> buildbot # [    0.024176] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23140vm-test-run-scheduled-effects> buildbot # [    0.024179] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)141vm-test-run-scheduled-effects> buildbot # [    0.024181] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)142vm-test-run-scheduled-effects> buildbot # [    0.024182] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)143vm-test-run-scheduled-effects> buildbot # [    0.024183] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)144vm-test-run-scheduled-effects> buildbot # [    0.024184] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)145vm-test-run-scheduled-effects> buildbot # [    0.024186] ACPI: Using ACPI (MADT) for SMP configuration information146vm-test-run-scheduled-effects> buildbot # [    0.024187] ACPI: HPET id: 0x8086a201 base: 0xfed00000147vm-test-run-scheduled-effects> buildbot # [    0.024191] TSC deadline timer available148vm-test-run-scheduled-effects> buildbot # [    0.024195] CPU topo: Max. logical packages:   1149vm-test-run-scheduled-effects> buildbot # [    0.024195] CPU topo: Max. logical dies:       1150vm-test-run-scheduled-effects> buildbot # [    0.024196] CPU topo: Max. dies per package:   1151vm-test-run-scheduled-effects> buildbot # [    0.024199] CPU topo: Max. threads per core:   1152vm-test-run-scheduled-effects> buildbot # [    0.024200] CPU topo: Num. cores per package:     1153vm-test-run-scheduled-effects> buildbot # [    0.024200] CPU topo: Num. threads per package:   1154vm-test-run-scheduled-effects> buildbot # [    0.024200] CPU topo: Allowing 1 present CPUs plus 0 hotplug CPUs155vm-test-run-scheduled-effects> buildbot # [    0.024218] kvm-guest: APIC: eoi() replaced with kvm_guest_apic_eoi_write()156vm-test-run-scheduled-effects> buildbot # [    0.024251] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]157vm-test-run-scheduled-effects> buildbot # [    0.024253] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x000fffff]158vm-test-run-scheduled-effects> buildbot # [    0.024254] [mem 0x40000000-0xfeffbfff] available for PCI devices159vm-test-run-scheduled-effects> buildbot # [    0.024255] Booting paravirtualized kernel on KVM160vm-test-run-scheduled-effects> buildbot # [    0.024258] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns161vm-test-run-scheduled-effects> buildbot # [    0.028707] setup_percpu: NR_CPUS:384 nr_cpumask_bits:1 nr_cpu_ids:1 nr_node_ids:1162vm-test-run-scheduled-effects> buildbot # [    0.031007] percpu: Embedded 98 pages/cpu s278528 r8192 d114688 u2097152163vm-test-run-scheduled-effects> buildbot # [    0.031049] kvm-guest: PV spinlocks disabled, single CPU164vm-test-run-scheduled-effects> buildbot # [    0.031050] Kernel command line: console=ttyS0 console=tty0 panic=1 boot.panic_on_fail clocksource=acpi_pm root=fstab loglevel=7 net.ifnames=0 lsm=landlock,yama,bpf init=/nix/store/nswbpy9j7m34fi0s5bq3b34fk13smbw6-nixos-system-buildbot-test/init regInfo=/nix/store/p548j36n5rvkryzq8vgqxcwqpjb7m6i8-closure-info/registration console=ttyS0,115200n8 console=tty0165vm-test-run-scheduled-effects> buildbot # [    0.031137] Unknown kernel command line parameters "regInfo=/nix/store/p548j36n5rvkryzq8vgqxcwqpjb7m6i8-closure-info/registration", will be passed to user space.166vm-test-run-scheduled-effects> buildbot # [    0.031149] random: crng init done167vm-test-run-scheduled-effects> buildbot # [    0.031149] printk: log buffer data + meta data: 262144 + 917504 = 1179648 bytes168vm-test-run-scheduled-effects> buildbot # [    0.031172] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)169vm-test-run-scheduled-effects> buildbot # [    0.031710] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes, linear)170vm-test-run-scheduled-effects> buildbot # [    0.031740] Fallback order for Node 0: 0171vm-test-run-scheduled-effects> buildbot # [    0.031742] Built 1 zonelists, mobility grouping on.  Total pages: 262009172vm-test-run-scheduled-effects> buildbot # [    0.031743] Policy zone: DMA32173vm-test-run-scheduled-effects> buildbot # [    0.034152] mem auto-init: stack:all(zero), heap alloc:on, heap free:off174vm-test-run-scheduled-effects> buildbot # [    0.036428] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1175vm-test-run-scheduled-effects> buildbot # [    0.038620] allocated 2097152 bytes of page_ext176vm-test-run-scheduled-effects> buildbot # [    0.047854] ftrace: allocating 48583 entries in 192 pages177vm-test-run-scheduled-effects> buildbot # [    0.047856] ftrace: allocated 192 pages with 2 groups178vm-test-run-scheduled-effects> buildbot # [    0.048640] Dynamic Preempt: lazy179vm-test-run-scheduled-effects> buildbot # [    0.048773] rcu: Preemptible hierarchical RCU implementation.180vm-test-run-scheduled-effects> buildbot # [    0.048773] rcu: 	RCU event tracing is enabled.181vm-test-run-scheduled-effects> buildbot # [    0.048774] rcu: 	RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=1.182vm-test-run-scheduled-effects> buildbot # [    0.048775] 	Trampoline variant of Tasks RCU enabled.183vm-test-run-scheduled-effects> buildbot # [    0.048776] 	Rude variant of Tasks RCU enabled.184vm-test-run-scheduled-effects> buildbot # [    0.048776] 	Tracing variant of Tasks RCU enabled.185vm-test-run-scheduled-effects> buildbot # [    0.048777] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.186vm-test-run-scheduled-effects> buildbot # [    0.048777] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1187vm-test-run-scheduled-effects> buildbot # [    0.048833] RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.188vm-test-run-scheduled-effects> buildbot # [    0.048835] RCU Tasks Rude: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.189vm-test-run-scheduled-effects> buildbot # [    0.048835] RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.190vm-test-run-scheduled-effects> buildbot # [    0.053127] NR_IRQS: 24832, nr_irqs: 256, preallocated irqs: 16191vm-test-run-scheduled-effects> buildbot # [    0.053404] rcu: srcu_init: Setting srcu_struct sizes based on contention.192vm-test-run-scheduled-effects> buildbot # [    0.053509] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)193vm-test-run-scheduled-effects> buildbot # [    0.060763] Console: colour VGA+ 80x25194vm-test-run-scheduled-effects> buildbot # [    0.060767] printk: legacy console [tty0] enabled195vm-test-run-scheduled-effects> buildbot # [    0.101427] printk: legacy console [ttyS0] enabled196vm-test-run-scheduled-effects> buildbot # [    0.289259] ACPI: Core revision 20250807197vm-test-run-scheduled-effects> buildbot # [    0.290808] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns198vm-test-run-scheduled-effects> buildbot # [    0.293663] APIC: Switch to symmetric I/O mode setup199vm-test-run-scheduled-effects> buildbot # [    0.295403] x2apic enabled200vm-test-run-scheduled-effects> buildbot # [    0.296639] APIC: Switched APIC routing to: physical x2apic201vm-test-run-scheduled-effects> buildbot # [    0.299484] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1202vm-test-run-scheduled-effects> buildbot # [    0.301308] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229840d1729, max_idle_ns: 440795276167 ns203vm-test-run-scheduled-effects> buildbot # [    0.304400] Calibrating delay loop (skipped) preset value.. 4800.02 BogoMIPS (lpj=2400010)204vm-test-run-scheduled-effects> buildbot # [    0.306514] x86/cpu: User Mode Instruction Prevention (UMIP) activated205vm-test-run-scheduled-effects> buildbot # [    0.307578] Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127206vm-test-run-scheduled-effects> buildbot # [    0.308398] Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0207vm-test-run-scheduled-effects> buildbot # [    0.309403] mitigations: Enabled attack vectors: user_kernel, user_user, guest_host, guest_guest, SMT mitigations: auto208vm-test-run-scheduled-effects> buildbot # [    0.310398] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl209vm-test-run-scheduled-effects> buildbot # [    0.311398] Transient Scheduler Attacks: Mitigation: Clear CPU buffers210vm-test-run-scheduled-effects> buildbot # [    0.312398] Spectre V2 : Mitigation: Enhanced / Automatic IBRS211vm-test-run-scheduled-effects> buildbot # [    0.313398] Speculative Return Stack Overflow: Mitigation: Safe RET212vm-test-run-scheduled-effects> buildbot # [    0.315398] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization213vm-test-run-scheduled-effects> buildbot # [    0.317404] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier214vm-test-run-scheduled-effects> buildbot # [    0.318398] active return thunk: srso_alias_return_thunk215vm-test-run-scheduled-effects> buildbot # [    0.320426] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'216vm-test-run-scheduled-effects> buildbot # [    0.321398] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'217vm-test-run-scheduled-effects> buildbot # [    0.323397] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'218vm-test-run-scheduled-effects> buildbot # [    0.325398] x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask'219vm-test-run-scheduled-effects> buildbot # [    0.326398] x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256'220vm-test-run-scheduled-effects> buildbot # [    0.327398] x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256'221vm-test-run-scheduled-effects> buildbot # [    0.328398] x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers'222vm-test-run-scheduled-effects> buildbot # [    0.329398] x86/fpu: Supporting XSAVE feature 0x800: 'Control-flow User registers'223vm-test-run-scheduled-effects> buildbot # [    0.331398] x86/fpu: Supporting XSAVE feature 0x1000: 'Control-flow Kernel registers (KVM only)'224vm-test-run-scheduled-effects> buildbot # [    0.333398] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256225vm-test-run-scheduled-effects> buildbot # [    0.334398] x86/fpu: xstate_offset[5]:  832, xstate_sizes[5]:   64226vm-test-run-scheduled-effects> buildbot # [    0.335398] x86/fpu: xstate_offset[6]:  896, xstate_sizes[6]:  512227vm-test-run-scheduled-effects> buildbot # [    0.336398] x86/fpu: xstate_offset[7]: 1408, xstate_sizes[7]: 1024228vm-test-run-scheduled-effects> buildbot # [    0.337398] x86/fpu: xstate_offset[9]: 2432, xstate_sizes[9]:    8229vm-test-run-scheduled-effects> buildbot # [    0.339398] x86/fpu: xstate_offset[11]: 2440, xstate_sizes[11]:   16230vm-test-run-scheduled-effects> buildbot # [    0.341398] x86/fpu: xstate_offset[12]: 2456, xstate_sizes[12]:   24231vm-test-run-scheduled-effects> buildbot # [    0.342398] x86/fpu: Enabled xstate features 0x1ae7, context size is 2480 bytes, using 'compacted' format.232vm-test-run-scheduled-effects> buildbot # [    0.376251] Freeing SMP alternatives memory: 44K233vm-test-run-scheduled-effects> buildbot # [    0.377399] pid_max: default: 32768 minimum: 301234vm-test-run-scheduled-effects> buildbot # [    0.378502] LSM: initializing lsm=capability,landlock,yama,bpf,ima235vm-test-run-scheduled-effects> buildbot # [    0.380503] landlock: Up and running.236vm-test-run-scheduled-effects> buildbot # [    0.382265] Yama: becoming mindful.237vm-test-run-scheduled-effects> buildbot # [    0.383607] LSM support for eBPF active238vm-test-run-scheduled-effects> buildbot # [    0.384504] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)239vm-test-run-scheduled-effects> buildbot # [    0.386426] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)240vm-test-run-scheduled-effects> buildbot # [    0.389759] smpboot: CPU0: AMD EPYC 9654 96-Core Processor (family: 0x19, model: 0x11, stepping: 0x1)241vm-test-run-scheduled-effects> buildbot # [    0.390939] Performance Events: Fam17h+ core perfctr, AMD PMU driver.242vm-test-run-scheduled-effects> buildbot # [    0.391408] ... version:                   2243vm-test-run-scheduled-effects> buildbot # [    0.392400] ... bit width:                 48244vm-test-run-scheduled-effects> buildbot # [    0.393399] ... generic counters:          6245vm-test-run-scheduled-effects> buildbot # [    0.394399] ... generic bitmap:            000000000000003f246vm-test-run-scheduled-effects> buildbot # [    0.395399] ... fixed-purpose counters:    0247vm-test-run-scheduled-effects> buildbot # [    0.396399] ... fixed-purpose bitmap:      0000000000000000248vm-test-run-scheduled-effects> buildbot # [    0.397399] ... value mask:                0000ffffffffffff249vm-test-run-scheduled-effects> buildbot # [    0.398399] ... max period:                00007fffffffffff250vm-test-run-scheduled-effects> buildbot # [    0.399400] ... global_ctrl mask:          000000000000003f251vm-test-run-scheduled-effects> buildbot # [    0.400500] signal: max sigframe size: 3376252vm-test-run-scheduled-effects> buildbot # [    0.401542] rcu: Hierarchical SRCU implementation.253vm-test-run-scheduled-effects> buildbot # [    0.402404] rcu: 	Max phase no-delay instances is 400.254vm-test-run-scheduled-effects> buildbot # [    0.407936] smp: Bringing up secondary CPUs ...255vm-test-run-scheduled-effects> buildbot # [    0.408416] smp: Brought up 1 node, 1 CPU256vm-test-run-scheduled-effects> buildbot # [    0.409402] smpboot: Total of 1 processors activated (4800.02 BogoMIPS)257vm-test-run-scheduled-effects> buildbot # [    0.410571] Memory: 942608K/1048036K available (17155K kernel code, 2721K rwdata, 13560K rodata, 3636K init, 3020K bss, 98052K reserved, 0K cma-reserved)258vm-test-run-scheduled-effects> buildbot # [    0.411645] devtmpfs: initialized259vm-test-run-scheduled-effects> buildbot # [    0.412623] x86/mm: Memory block size: 128MB260vm-test-run-scheduled-effects> buildbot # [    0.414338] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns261vm-test-run-scheduled-effects> buildbot # [    0.415437] posixtimers hash table entries: 512 (order: 1, 8192 bytes, linear)262vm-test-run-scheduled-effects> buildbot # [    0.416430] futex hash table entries: 256 (16384 bytes on 1 NUMA nodes, total 16 KiB, linear).263vm-test-run-scheduled-effects> buildbot # [    0.417506] pinctrl core: initialized pinctrl subsystem264vm-test-run-scheduled-effects> buildbot # [    0.418741] PM: RTC time: 06:13:29, date: 2026-06-28265vm-test-run-scheduled-effects> buildbot # [    0.421959] NET: Registered PF_NETLINK/PF_ROUTE protocol family266vm-test-run-scheduled-effects> buildbot # [    0.422766] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations267vm-test-run-scheduled-effects> buildbot # [    0.423421] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations268vm-test-run-scheduled-effects> buildbot # [    0.424545] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations269vm-test-run-scheduled-effects> buildbot # [    0.425411] audit: initializing netlink subsys (disabled)270vm-test-run-scheduled-effects> buildbot # [    0.426658] thermal_sys: Registered thermal governor 'fair_share'271vm-test-run-scheduled-effects> buildbot # [    0.426661] thermal_sys: Registered thermal governor 'bang_bang'272vm-test-run-scheduled-effects> buildbot # [    0.427400] thermal_sys: Registered thermal governor 'step_wise'273vm-test-run-scheduled-effects> buildbot # [    0.428404] audit: type=2000 audit(1782627209.145:1): state=initialized audit_enabled=0 res=1274vm-test-run-scheduled-effects> buildbot # [    0.430403] thermal_sys: Registered thermal governor 'user_space'275vm-test-run-scheduled-effects> buildbot # [    0.430405] thermal_sys: Registered thermal governor 'power_allocator'276vm-test-run-scheduled-effects> buildbot # [    0.431420] cpuidle: using governor menu277vm-test-run-scheduled-effects> buildbot # [    0.434620] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5278vm-test-run-scheduled-effects> buildbot # [    0.435688] PCI: Using configuration type 1 for base access279vm-test-run-scheduled-effects> buildbot # [    0.436400] PCI: Using configuration type 1 for extended access280vm-test-run-scheduled-effects> buildbot # [    0.437597] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.281vm-test-run-scheduled-effects> buildbot # [    0.442690] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages282vm-test-run-scheduled-effects> buildbot # [    0.443400] HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page283vm-test-run-scheduled-effects> buildbot # [    0.448399] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages284vm-test-run-scheduled-effects> buildbot # [    0.449400] HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page285vm-test-run-scheduled-effects> buildbot # [    0.459802] ACPI: Added _OSI(Module Device)286vm-test-run-scheduled-effects> buildbot # [    0.460401] ACPI: Added _OSI(Processor Device)287vm-test-run-scheduled-effects> buildbot # [    0.465399] ACPI: Added _OSI(Processor Aggregator Device)288vm-test-run-scheduled-effects> buildbot # [    0.470265] ACPI: 1 ACPI AML tables successfully acquired and loaded289vm-test-run-scheduled-effects> buildbot # [    0.474306] ACPI: Interpreter enabled290vm-test-run-scheduled-effects> buildbot # [    0.475316] ACPI: PM: (supports S0 S3 S4 S5)291vm-test-run-scheduled-effects> buildbot # [    0.478399] ACPI: Using IOAPIC for interrupt routing292vm-test-run-scheduled-effects> buildbot # [    0.479420] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug293vm-test-run-scheduled-effects> buildbot # [    0.482398] PCI: Using E820 reservations for host bridge windows294vm-test-run-scheduled-effects> buildbot # [    0.483552] ACPI: Enabled 2 GPEs in block 00 to 0F295vm-test-run-scheduled-effects> buildbot # [    0.491494] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])296vm-test-run-scheduled-effects> buildbot # [    0.492406] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]297vm-test-run-scheduled-effects> buildbot # [    0.493856] acpiphp: Slot [3] registered298vm-test-run-scheduled-effects> buildbot # [    0.494487] acpiphp: Slot [4] registered299vm-test-run-scheduled-effects> buildbot # [    0.495457] acpiphp: Slot [5] registered300vm-test-run-scheduled-effects> buildbot # [    0.496459] acpiphp: Slot [6] registered301vm-test-run-scheduled-effects> buildbot # [    0.497551] acpiphp: Slot [7] registered302vm-test-run-scheduled-effects> buildbot # [    0.498514] acpiphp: Slot [8] registered303vm-test-run-scheduled-effects> buildbot # [    0.499469] acpiphp: Slot [9] registered304vm-test-run-scheduled-effects> buildbot # [    0.500458] acpiphp: Slot [10] registered305vm-test-run-scheduled-effects> buildbot # [    0.501462] acpiphp: Slot [11] registered306vm-test-run-scheduled-effects> buildbot # [    0.502472] acpiphp: Slot [12] registered307vm-test-run-scheduled-effects> buildbot # [    0.503459] acpiphp: Slot [13] registered308vm-test-run-scheduled-effects> buildbot # [    0.504433] acpiphp: Slot [14] registered309vm-test-run-scheduled-effects> buildbot # [    0.505432] acpiphp: Slot [15] registered310vm-test-run-scheduled-effects> buildbot # [    0.506450] acpiphp: Slot [16] registered311vm-test-run-scheduled-effects> buildbot # [    0.507432] acpiphp: Slot [17] registered312vm-test-run-scheduled-effects> buildbot # [    0.508432] acpiphp: Slot [18] registered313vm-test-run-scheduled-effects> buildbot # [    0.509446] acpiphp: Slot [19] registered314vm-test-run-scheduled-effects> buildbot # [    0.510433] acpiphp: Slot [20] registered315vm-test-run-scheduled-effects> buildbot # [    0.511432] acpiphp: Slot [21] registered316vm-test-run-scheduled-effects> buildbot # [    0.512433] acpiphp: Slot [22] registered317vm-test-run-scheduled-effects> buildbot # [    0.513446] acpiphp: Slot [23] registered318vm-test-run-scheduled-effects> buildbot # [    0.514433] acpiphp: Slot [24] registered319vm-test-run-scheduled-effects> buildbot # [    0.515433] acpiphp: Slot [25] registered320vm-test-run-scheduled-effects> buildbot # [    0.516452] acpiphp: Slot [26] registered321vm-test-run-scheduled-effects> buildbot # [    0.517446] acpiphp: Slot [27] registered322vm-test-run-scheduled-effects> buildbot # [    0.518434] acpiphp: Slot [28] registered323vm-test-run-scheduled-effects> buildbot # [    0.519442] acpiphp: Slot [29] registered324vm-test-run-scheduled-effects> buildbot # [    0.520434] acpiphp: Slot [30] registered325vm-test-run-scheduled-effects> buildbot # [    0.521453] acpiphp: Slot [31] registered326vm-test-run-scheduled-effects> buildbot # [    0.522423] PCI host bridge to bus 0000:00327vm-test-run-scheduled-effects> buildbot # [    0.523407] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]328vm-test-run-scheduled-effects> buildbot # [    0.524401] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]329vm-test-run-scheduled-effects> buildbot # [    0.525400] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]330vm-test-run-scheduled-effects> buildbot # [    0.526400] pci_bus 0000:00: root bus resource [mem 0x40000000-0xfebfffff window]331vm-test-run-scheduled-effects> buildbot # [    0.527400] pci_bus 0000:00: root bus resource [mem 0x100000000-0x17fffffff window]332vm-test-run-scheduled-effects> buildbot # [    0.528401] pci_bus 0000:00: root bus resource [bus 00-ff]333vm-test-run-scheduled-effects> buildbot # [    0.529787] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 conventional PCI endpoint334vm-test-run-scheduled-effects> buildbot # [    0.531381] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 conventional PCI endpoint335vm-test-run-scheduled-effects> buildbot # [    0.533297] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 conventional PCI endpoint336vm-test-run-scheduled-effects> buildbot # [    0.536282] pci 0000:00:01.1: BAR 4 [io  0xc1e0-0xc1ef]337vm-test-run-scheduled-effects> buildbot # [    0.537498] pci 0000:00:01.1: BAR 0 [io  0x01f0-0x01f7]: legacy IDE quirk338vm-test-run-scheduled-effects> buildbot # [    0.538400] pci 0000:00:01.1: BAR 1 [io  0x03f6]: legacy IDE quirk339vm-test-run-scheduled-effects> buildbot # [    0.539400] pci 0000:00:01.1: BAR 2 [io  0x0170-0x0177]: legacy IDE quirk340vm-test-run-scheduled-effects> buildbot # [    0.540400] pci 0000:00:01.1: BAR 3 [io  0x0376]: legacy IDE quirk341vm-test-run-scheduled-effects> buildbot # [    0.541725] pci 0000:00:01.2: [8086:7020] type 00 class 0x0c0300 conventional PCI endpoint342vm-test-run-scheduled-effects> buildbot # [    0.543490] pci 0000:00:01.2: BAR 4 [io  0xc100-0xc11f]343vm-test-run-scheduled-effects> buildbot # [    0.545776] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 conventional PCI endpoint344vm-test-run-scheduled-effects> buildbot # [    0.547387] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI345vm-test-run-scheduled-effects> buildbot # [    0.548414] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB346vm-test-run-scheduled-effects> buildbot # [    0.549851] pci 0000:00:02.0: [1234:1111] type 00 class 0x030000 conventional PCI endpoint347vm-test-run-scheduled-effects> buildbot # [    0.552477] pci 0000:00:02.0: BAR 0 [mem 0xfd000000-0xfdffffff pref]348vm-test-run-scheduled-effects> buildbot # [    0.553463] pci 0000:00:02.0: BAR 2 [mem 0xfebd0000-0xfebd0fff]349vm-test-run-scheduled-effects> buildbot # [    0.554453] pci 0000:00:02.0: ROM [mem 0xfebc0000-0xfebcffff pref]350vm-test-run-scheduled-effects> buildbot # [    0.555632] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]351vm-test-run-scheduled-effects> buildbot # [    0.557609] pci 0000:00:03.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint352vm-test-run-scheduled-effects> buildbot # [    0.560439] pci 0000:00:03.0: BAR 0 [io  0xc120-0xc13f]353vm-test-run-scheduled-effects> buildbot # [    0.561415] pci 0000:00:03.0: BAR 1 [mem 0xfebd1000-0xfebd1fff]354vm-test-run-scheduled-effects> buildbot # [    0.562453] pci 0000:00:03.0: BAR 4 [mem 0xfe000000-0xfe003fff 64bit pref]355vm-test-run-scheduled-effects> buildbot # [    0.563428] pci 0000:00:03.0: ROM [mem 0xfeb40000-0xfeb7ffff pref]356vm-test-run-scheduled-effects> buildbot # [    0.566632] pci 0000:00:04.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint357vm-test-run-scheduled-effects> buildbot # [    0.569442] pci 0000:00:04.0: BAR 0 [io  0xc140-0xc15f]358vm-test-run-scheduled-effects> buildbot # [    0.570415] pci 0000:00:04.0: BAR 1 [mem 0xfebd2000-0xfebd2fff]359vm-test-run-scheduled-effects> buildbot # [    0.571453] pci 0000:00:04.0: BAR 4 [mem 0xfe004000-0xfe007fff 64bit pref]360vm-test-run-scheduled-effects> buildbot # [    0.574530] pci 0000:00:05.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint361vm-test-run-scheduled-effects> buildbot # [    0.577424] pci 0000:00:05.0: BAR 0 [io  0xc080-0xc0bf]362vm-test-run-scheduled-effects> buildbot # [    0.578416] pci 0000:00:05.0: BAR 1 [mem 0xfebd3000-0xfebd3fff]363vm-test-run-scheduled-effects> buildbot # [    0.579454] pci 0000:00:05.0: BAR 4 [mem 0xfe008000-0xfe00bfff 64bit pref]364vm-test-run-scheduled-effects> buildbot # [    0.582627] pci 0000:00:06.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint365vm-test-run-scheduled-effects> buildbot # [    0.585400] pci 0000:00:06.0: BAR 0 [io  0xc160-0xc17f]366vm-test-run-scheduled-effects> buildbot # [    0.587416] pci 0000:00:06.0: BAR 1 [mem 0xfebd4000-0xfebd4fff]367vm-test-run-scheduled-effects> buildbot # [    0.588453] pci 0000:00:06.0: BAR 4 [mem 0xfe00c000-0xfe00ffff 64bit pref]368vm-test-run-scheduled-effects> buildbot # [    0.591478] pci 0000:00:07.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint369vm-test-run-scheduled-effects> buildbot # [    0.594437] pci 0000:00:07.0: BAR 0 [io  0xc180-0xc19f]370vm-test-run-scheduled-effects> buildbot # [    0.595415] pci 0000:00:07.0: BAR 1 [mem 0xfebd5000-0xfebd5fff]371vm-test-run-scheduled-effects> buildbot # [    0.596454] pci 0000:00:07.0: BAR 4 [mem 0xfe010000-0xfe013fff 64bit pref]372vm-test-run-scheduled-effects> buildbot # [    0.599414] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint373vm-test-run-scheduled-effects> buildbot # [    0.602472] pci 0000:00:08.0: BAR 0 [io  0xc000-0xc07f]374vm-test-run-scheduled-effects> buildbot # [    0.603414] pci 0000:00:08.0: BAR 1 [mem 0xfebd6000-0xfebd6fff]375vm-test-run-scheduled-effects> buildbot # [    0.604454] pci 0000:00:08.0: BAR 4 [mem 0xfe014000-0xfe017fff 64bit pref]376vm-test-run-scheduled-effects> buildbot # [    0.607974] pci 0000:00:09.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint377vm-test-run-scheduled-effects> buildbot # [    0.609415] pci 0000:00:09.0: BAR 0 [io  0xc1a0-0xc1bf]378vm-test-run-scheduled-effects> buildbot # [    0.610414] pci 0000:00:09.0: BAR 1 [mem 0xfebd7000-0xfebd7fff]379vm-test-run-scheduled-effects> buildbot # [    0.611453] pci 0000:00:09.0: BAR 4 [mem 0xfe018000-0xfe01bfff 64bit pref]380vm-test-run-scheduled-effects> buildbot # [    0.612415] pci 0000:00:09.0: ROM [mem 0xfeb80000-0xfebbffff pref]381vm-test-run-scheduled-effects> buildbot # [    0.615379] pci 0000:00:0a.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint382vm-test-run-scheduled-effects> buildbot # [    0.617427] pci 0000:00:0a.0: BAR 1 [mem 0xfebd8000-0xfebd8fff]383vm-test-run-scheduled-effects> buildbot # [    0.618727] pci 0000:00:0a.0: BAR 4 [mem 0xfe01c000-0xfe01ffff 64bit pref]384vm-test-run-scheduled-effects> buildbot # [    0.621414] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint385vm-test-run-scheduled-effects> buildbot # [    0.624153] pci 0000:00:0b.0: BAR 0 [io  0xc0c0-0xc0ff]386vm-test-run-scheduled-effects> buildbot # [    0.625414] pci 0000:00:0b.0: BAR 1 [mem 0xfebd9000-0xfebd9fff]387vm-test-run-scheduled-effects> buildbot # [    0.626453] pci 0000:00:0b.0: BAR 4 [mem 0xfe020000-0xfe023fff 64bit pref]388vm-test-run-scheduled-effects> buildbot # [    0.629427] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint389vm-test-run-scheduled-effects> buildbot # [    0.631436] pci 0000:00:0c.0: BAR 0 [io  0xc1c0-0xc1df]390vm-test-run-scheduled-effects> buildbot # [    0.632415] pci 0000:00:0c.0: BAR 1 [mem 0xfebda000-0xfebdafff]391vm-test-run-scheduled-effects> buildbot # [    0.633462] pci 0000:00:0c.0: BAR 4 [mem 0xfe024000-0xfe027fff 64bit pref]392vm-test-run-scheduled-effects> buildbot # [    0.641813] ACPI: PCI: Interrupt link LNKA configured for IRQ 10393vm-test-run-scheduled-effects> buildbot # [    0.642626] ACPI: PCI: Interrupt link LNKB configured for IRQ 10394vm-test-run-scheduled-effects> buildbot # [    0.643599] ACPI: PCI: Interrupt link LNKC configured for IRQ 11395vm-test-run-scheduled-effects> buildbot # [    0.644592] ACPI: PCI: Interrupt link LNKD configured for IRQ 11396vm-test-run-scheduled-effects> buildbot # [    0.645510] ACPI: PCI: Interrupt link LNKS configured for IRQ 9397vm-test-run-scheduled-effects> buildbot # [    0.647618] iommu: Default domain type: Translated398vm-test-run-scheduled-effects> buildbot # [    0.648411] iommu: DMA domain TLB invalidation policy: lazy mode399vm-test-run-scheduled-effects> buildbot # [    0.649712] ACPI: bus type USB registered400vm-test-run-scheduled-effects> buildbot # [    0.650460] usbcore: registered new interface driver usbfs401vm-test-run-scheduled-effects> buildbot # [    0.651431] usbcore: registered new interface driver hub402vm-test-run-scheduled-effects> buildbot # [    0.652411] usbcore: registered new device driver usb403vm-test-run-scheduled-effects> buildbot # [    0.654421] NetLabel: Initializing404vm-test-run-scheduled-effects> buildbot # [    0.655400] NetLabel:  domain hash size = 128405vm-test-run-scheduled-effects> buildbot # [    0.656399] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO406vm-test-run-scheduled-effects> buildbot # [    0.657448] NetLabel:  unlabeled traffic allowed by default407vm-test-run-scheduled-effects> buildbot # [    0.658415] PCI: Using ACPI for IRQ routing408vm-test-run-scheduled-effects> buildbot # [    0.660069] pci 0000:00:02.0: vgaarb: setting as boot VGA device409vm-test-run-scheduled-effects> buildbot # [    0.660395] pci 0000:00:02.0: vgaarb: bridge control possible410vm-test-run-scheduled-effects> buildbot # [    0.660395] pci 0000:00:02.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none411vm-test-run-scheduled-effects> buildbot # [    0.660403] vgaarb: loaded412vm-test-run-scheduled-effects> buildbot # [    0.661580] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0413vm-test-run-scheduled-effects> buildbot # [    0.662400] hpet0: 3 comparators, 64-bit 100.000000 MHz counter414vm-test-run-scheduled-effects> buildbot # [    0.668499] clocksource: Switched to clocksource kvm-clock415vm-test-run-scheduled-effects> buildbot # [    0.670828] VFS: Disk quotas dquot_6.6.0416vm-test-run-scheduled-effects> buildbot # [    0.674044] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)417vm-test-run-scheduled-effects> buildbot # [    0.676351] pnp: PnP ACPI init418vm-test-run-scheduled-effects> buildbot # [    0.678089] pnp: PnP ACPI: found 6 devices419vm-test-run-scheduled-effects> buildbot # [    0.686451] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns420vm-test-run-scheduled-effects> buildbot # [    0.689062] clocksource: Switched to clocksource acpi_pm421vm-test-run-scheduled-effects> buildbot # [    0.690808] NET: Registered PF_INET protocol family422vm-test-run-scheduled-effects> buildbot # [    0.692574] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)423vm-test-run-scheduled-effects> buildbot # [    0.711193] tcp_listen_portaddr_hash hash table entries: 512 (order: 1, 8192 bytes, linear)424vm-test-run-scheduled-effects> buildbot # [    0.713807] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)425vm-test-run-scheduled-effects> buildbot # [    0.716166] TCP established hash table entries: 8192 (order: 4, 65536 bytes, linear)426vm-test-run-scheduled-effects> buildbot # [    0.718481] TCP bind hash table entries: 8192 (order: 6, 262144 bytes, linear)427vm-test-run-scheduled-effects> buildbot # [    0.720655] TCP: Hash tables configured (established 8192 bind 8192)428vm-test-run-scheduled-effects> buildbot # [    0.722619] MPTCP token hash table entries: 1024 (order: 3, 24576 bytes, linear)429vm-test-run-scheduled-effects> buildbot # [    0.724922] UDP hash table entries: 512 (order: 3, 32768 bytes, linear)430vm-test-run-scheduled-effects> buildbot # [    0.726954] UDP-Lite hash table entries: 512 (order: 3, 32768 bytes, linear)431vm-test-run-scheduled-effects> buildbot # [    0.729153] NET: Registered PF_UNIX/PF_LOCAL protocol family432vm-test-run-scheduled-effects> buildbot # [    0.730891] NET: Registered PF_XDP protocol family433vm-test-run-scheduled-effects> buildbot # [    0.732455] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]434vm-test-run-scheduled-effects> buildbot # [    0.734320] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]435vm-test-run-scheduled-effects> buildbot # [    0.736187] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]436vm-test-run-scheduled-effects> buildbot # [    0.738224] pci_bus 0000:00: resource 7 [mem 0x40000000-0xfebfffff window]437vm-test-run-scheduled-effects> buildbot # [    0.740259] pci_bus 0000:00: resource 8 [mem 0x100000000-0x17fffffff window]438vm-test-run-scheduled-effects> buildbot # [    0.742440] pci 0000:00:01.0: PIIX3: Enabling Passive Release439vm-test-run-scheduled-effects> buildbot # [    0.744240] pci 0000:00:00.0: Limiting direct PCI/PCI transfers440vm-test-run-scheduled-effects> buildbot # [    0.747614] ACPI: \_SB_.LNKD: Enabled at IRQ 11441vm-test-run-scheduled-effects> buildbot # [    0.750951] PCI: CLS 0 bytes, default 64442vm-test-run-scheduled-effects> buildbot # [    0.752517] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229840d1729, max_idle_ns: 440795276167 ns443vm-test-run-scheduled-effects> buildbot # [    0.755549] Trying to unpack rootfs image as initramfs...444vm-test-run-scheduled-effects> buildbot # [    0.803461] Initialise system trusted keyrings445vm-test-run-scheduled-effects> buildbot # [    0.808230] workingset: timestamp_bits=40 max_order=18 bucket_order=0446vm-test-run-scheduled-effects> buildbot # [    0.835509] Key type asymmetric registered447vm-test-run-scheduled-effects> buildbot # [    0.836877] Asymmetric key parser 'x509' registered448vm-test-run-scheduled-effects> buildbot # [    0.842092] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)449vm-test-run-scheduled-effects> buildbot # [    0.848081] io scheduler mq-deadline registered450vm-test-run-scheduled-effects> buildbot # [    0.849520] io scheduler kyber registered451vm-test-run-scheduled-effects> buildbot # [    0.853698] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled452vm-test-run-scheduled-effects> buildbot # [    0.858409] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A453vm-test-run-scheduled-effects> buildbot # [    0.867420] Linux agpgart interface v0.103454vm-test-run-scheduled-effects> buildbot # [    0.868852] ACPI: bus type drm_connector registered455vm-test-run-scheduled-effects> buildbot # [    0.874501] usbcore: registered new interface driver usbserial_generic456vm-test-run-scheduled-effects> buildbot # [    0.876486] usbserial: USB Serial support registered for generic457vm-test-run-scheduled-effects> buildbot # [    0.882049] amd_pstate: The CPPC feature is supported but currently disabled by the BIOS.458vm-test-run-scheduled-effects> buildbot # [    0.882049] Please enable it if your BIOS has the CPPC option.459vm-test-run-scheduled-effects> buildbot # [    0.886066] amd_pstate: the _CPC object is not present in SBIOS or ACPI disabled460vm-test-run-scheduled-effects> buildbot # [    0.893219] drop_monitor: Initializing network drop monitor service461vm-test-run-scheduled-effects> buildbot # [    0.895331] NET: Registered PF_INET6 protocol family462vm-test-run-scheduled-effects> buildbot # [    0.902608] Segment Routing with IPv6463vm-test-run-scheduled-effects> buildbot # [    0.907057] In-situ OAM (IOAM) with IPv6464vm-test-run-scheduled-effects> buildbot # [    0.908783] IPI shorthand broadcast: enabled465vm-test-run-scheduled-effects> buildbot # [    0.919892] sched_clock: Marking stable (675029787, 243984874)->(1120990659, -201975998)466vm-test-run-scheduled-effects> buildbot # [    0.926274] registered taskstats version 1467vm-test-run-scheduled-effects> buildbot # [    0.927866] Loading compiled-in X.509 certificates468vm-test-run-scheduled-effects> buildbot # [    0.948766] Demotion targets for Node 0: null469vm-test-run-scheduled-effects> buildbot # [    0.953087] Key type .fscrypt registered470vm-test-run-scheduled-effects> buildbot # [    0.954361] Key type fscrypt-provisioning registered471vm-test-run-scheduled-effects> buildbot # [    0.958164] ima: No TPM chip found, activating TPM-bypass!472vm-test-run-scheduled-effects> buildbot # [    0.959873] ima: Allocated hash algorithm: sha1473vm-test-run-scheduled-effects> buildbot # [    0.966074] ima: No architecture policies found474vm-test-run-scheduled-effects> buildbot # [    0.967710] PM:   Magic number: 14:905:216475vm-test-run-scheduled-effects> buildbot # [    0.972088] RAS: Correctable Errors collector initialized.476vm-test-run-scheduled-effects> buildbot # [    0.981924] clk: Disabling unused clocks477vm-test-run-scheduled-effects> buildbot # [    0.987038] PM: genpd: Disabling unused power domains478vm-test-run-scheduled-effects> buildbot # [    1.108815] Freeing initrd memory: 27528K479vm-test-run-scheduled-effects> buildbot # [    1.112888] Freeing unused decrypted memory: 2028K480vm-test-run-scheduled-effects> buildbot # [    1.116532] Freeing unused kernel image (initmem) memory: 3636K481vm-test-run-scheduled-effects> buildbot # [    1.118437] Write protecting the kernel read-only data: 32768k482vm-test-run-scheduled-effects> buildbot # [    1.121294] Freeing unused kernel image (text/rodata gap) memory: 1276K483vm-test-run-scheduled-effects> buildbot # [    1.123816] Freeing unused kernel image (rodata/data gap) memory: 776K484vm-test-run-scheduled-effects> buildbot # [    1.177158] x86/mm: Checked W+X mappings: passed, no W+X pages found.485vm-test-run-scheduled-effects> buildbot # [    1.179183] Run /init as init process486vm-test-run-scheduled-effects> buildbot # [    1.191053] systemd[1]: Inserted module 'autofs4'487vm-test-run-scheduled-effects> buildbot # [    1.208628] fuse: init (API version 7.45)488vm-test-run-scheduled-effects> buildbot # [    1.216322] ACPI: \_SB_.LNKC: Enabled at IRQ 10489vm-test-run-scheduled-effects> buildbot # [    1.225237] ACPI: \_SB_.LNKA: Enabled at IRQ 10490vm-test-run-scheduled-effects> buildbot # [    1.229957] ACPI: \_SB_.LNKB: Enabled at IRQ 11491vm-test-run-scheduled-effects> buildbot # [    1.270161] systemd[1]: Successfully made /usr/ read-only.492vm-test-run-scheduled-effects> buildbot # [    1.607764] systemd[1]: systemd 260.1 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -BTF -XKBCOMMON +UTMP +LIBARCHIVE)493vm-test-run-scheduled-effects> buildbot # [    1.616498] systemd[1]: Detected virtualization kvm.494vm-test-run-scheduled-effects> buildbot # [    1.618062] systemd[1]: Detected architecture x86-64.495vm-test-run-scheduled-effects> buildbot # [    1.619622] systemd[1]: Running in initrd.496vm-test-run-scheduled-effects> buildbot # [    1.621441] systemd[1]: Initializing machine ID from random generator.497vm-test-run-scheduled-effects> buildbot # [    1.623523] systemd[1]: Hostname set to <buildbot>.498vm-test-run-scheduled-effects> buildbot # [    1.677605] systemd[1]: Queued start job for default target Initrd Default Target.499vm-test-run-scheduled-effects> buildbot # [    1.736666] systemd[1]: Created slice Slice /system/modprobe.500vm-test-run-scheduled-effects> buildbot # [    1.738879] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.501vm-test-run-scheduled-effects> buildbot # [    1.741415] systemd[1]: Expecting device /dev/disk/by-label/nixos...502vm-test-run-scheduled-effects> buildbot # [    1.743455] systemd[1]: Reached target Path Units.503vm-test-run-scheduled-effects> buildbot # [    1.745131] systemd[1]: Reached target Slice Units.504vm-test-run-scheduled-effects> buildbot # [    1.746806] systemd[1]: Reached target Swaps.505vm-test-run-scheduled-effects> buildbot # [    1.748354] systemd[1]: Reached target Timer Units.506vm-test-run-scheduled-effects> buildbot # [    1.750224] systemd[1]: Listening on D-Bus System Message Bus Socket.507vm-test-run-scheduled-effects> buildbot # [    1.752401] systemd[1]: Listening on Journal Socket (/dev/log).508vm-test-run-scheduled-effects> buildbot # [    1.754497] systemd[1]: Listening on Journal Sockets.509vm-test-run-scheduled-effects> buildbot # [    1.756292] systemd[1]: Listening on udev Control Socket.510vm-test-run-scheduled-effects> buildbot # [    1.758201] systemd[1]: Listening on udev Kernel Socket.511vm-test-run-scheduled-effects> buildbot # [    1.759965] systemd[1]: Reached target Socket Units.512vm-test-run-scheduled-effects> buildbot # [    1.763905] systemd[1]: Starting Create List of Static Device Nodes...513vm-test-run-scheduled-effects> buildbot # [    1.771483] systemd[1]: Starting Load Kernel Module 9pnet_virtio...514vm-test-run-scheduled-effects> buildbot # [    1.784265] systemd[1]: Starting Load Kernel Module configfs...515vm-test-run-scheduled-effects> buildbot # [    1.803621] systemd[1]: Starting Journal Service...516vm-test-run-scheduled-effects> buildbot # [    1.819202] systemd[1]: Starting Load Kernel Modules...517vm-test-run-scheduled-effects> buildbot # [    1.821061] netfs: FS-Cache loaded518vm-test-run-scheduled-effects> buildbot # [    1.832109] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki519vm-test-run-scheduled-effects> buildbot # [    1.849605] 9pnet: Installing 9P2000 support520vm-test-run-scheduled-effects> buildbot # [    1.860620] systemd-journald[125]: Collecting audit messages is disabled.521vm-test-run-scheduled-effects> buildbot # [    1.876753] systemd[1]: Starting Coldplug All udev Devices...522vm-test-run-scheduled-effects> buildbot # [    1.904134] systemd[1]: Finished Create List of Static Device Nodes.523vm-test-run-scheduled-effects> buildbot # [    1.913849] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.524vm-test-run-scheduled-effects> buildbot # [    1.930281] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.525vm-test-run-scheduled-effects> buildbot # [    1.936525] systemd[1]: Finished Load Kernel Module 9pnet_virtio.526vm-test-run-scheduled-effects> buildbot # [    1.945055] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev527vm-test-run-scheduled-effects> buildbot # [    1.953426] systemd[1]: modprobe@configfs.service: Deactivated successfully.528vm-test-run-scheduled-effects> buildbot # [    1.966799] systemd[1]: Finished Load Kernel Module configfs.529vm-test-run-scheduled-effects> buildbot # [    1.985977] systemd[1]: Finished Load Kernel Modules.530vm-test-run-scheduled-effects> buildbot # [    1.992904] systemd[1]: Kernel Configuration File System skipped, unmet condition check ConditionPathExists=/sys/kernel/config531vm-test-run-scheduled-effects> buildbot # [    2.011135] systemd[1]: Starting Apply Kernel Variables...532vm-test-run-scheduled-effects> buildbot # [    2.029509] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...533vm-test-run-scheduled-effects> buildbot # [    2.058179] systemd[1]: Finished Apply Kernel Variables.534vm-test-run-scheduled-effects> buildbot # [    2.066622] systemd[1]: Started Journal Service.535vm-test-run-scheduled-effects> buildbot # [    1.825252] systemd-modules-load[127]: Inserted module 'dm_mod'536vm-test-run-scheduled-effects> buildbot # [    1.829603] systemd-modules-load[127]: Inserted module 'virtio_balloon'537vm-test-run-scheduled-effects> buildbot # [    1.831624] systemd-modules-load[127]: Inserted module 'virtio_gpu'538vm-test-run-scheduled-effects> buildbot # [    1.840672] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.539vm-test-run-scheduled-effects> buildbot # [    1.854903] systemd[1]: Starting Create Static Device Nodes in /dev...540vm-test-run-scheduled-effects> buildbot # [    1.880274] systemd[1]: Finished Create Static Device Nodes in /dev.541vm-test-run-scheduled-effects> buildbot # [    1.883703] systemd[1]: Reached target Preparation for Local File Systems.542vm-test-run-scheduled-effects> buildbot # [    1.887114] systemd[1]: Reached target Local File Systems.543vm-test-run-scheduled-effects> buildbot # [    1.890605] systemd[1]: Starting Create System Files and Directories...544vm-test-run-scheduled-effects> buildbot # [    1.899669] systemd[1]: Starting Rule-based Manager for Device Events and Files...545vm-test-run-scheduled-effects> buildbot # [    1.930261] systemd[1]: Finished Create System Files and Directories.546vm-test-run-scheduled-effects> buildbot # [    1.957340] systemd-udevd[162]: Using default interface naming scheme 'v260'.547vm-test-run-scheduled-effects> buildbot # [    1.995109] systemd[1]: Started Rule-based Manager for Device Events and Files.548vm-test-run-scheduled-effects> buildbot # [    2.057752] systemd[1]: Finished Coldplug All udev Devices.549vm-test-run-scheduled-effects> buildbot # [    2.061821] systemd[1]: Reached target System Initialization.550vm-test-run-scheduled-effects> buildbot # [    2.063604] systemd[1]: Reached target Basic System.551vm-test-run-scheduled-effects> buildbot # [    2.600624] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12552vm-test-run-scheduled-effects> buildbot # [    2.616169] uhci_hcd 0000:00:01.2: UHCI Host Controller553vm-test-run-scheduled-effects> buildbot # [    2.630364] serio: i8042 KBD port at 0x60,0x64 irq 1554vm-test-run-scheduled-effects> buildbot # [    2.631593] serio: i8042 AUX port at 0x60,0x64 irq 12555vm-test-run-scheduled-effects> buildbot # [    2.637451] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1556vm-test-run-scheduled-effects> buildbot # [    2.652076] uhci_hcd 0000:00:01.2: detected 2 ports557vm-test-run-scheduled-effects> buildbot # [    2.657399] SCSI subsystem initialized558vm-test-run-scheduled-effects> buildbot # [    2.663293] virtio_blk virtio5: 1/0/0 default/read/poll queues559vm-test-run-scheduled-effects> buildbot # [    2.665364] uhci_hcd 0000:00:01.2: irq 11, io port 0x0000c100560vm-test-run-scheduled-effects> buildbot # [    2.680595] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.18561vm-test-run-scheduled-effects> buildbot # [    2.688651] virtio_blk virtio5: [vda] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB)562vm-test-run-scheduled-effects> buildbot # [    2.700953] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1563vm-test-run-scheduled-effects> buildbot # [    2.714537] usb usb1: Product: UHCI Host Controller564vm-test-run-scheduled-effects> buildbot # [    2.726977] usb usb1: Manufacturer: Linux 6.18.36 uhci_hcd565vm-test-run-scheduled-effects> buildbot # [    2.728552] usb usb1: SerialNumber: 0000:00:01.2566vm-test-run-scheduled-effects> buildbot # [    2.744111] hub 1-0:1.0: USB hub found567vm-test-run-scheduled-effects> buildbot # [    2.756132] hub 1-0:1.0: 2 ports detected568vm-test-run-scheduled-effects> buildbot # [    2.542186] systemd[1]: Starting Virtual Console Setup...569vm-test-run-scheduled-effects> buildbot # [    2.558733] (udev-worker)[168]: Network interface NamePolicy= disabled on kernel command line.570vm-test-run-scheduled-effects> buildbot # [    2.572310] (udev-worker)[169]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.571vm-test-run-scheduled-effects> buildbot # [    2.576152] (udev-worker)[169]: Network interface NamePolicy= disabled on kernel command line.572vm-test-run-scheduled-effects> buildbot # [    2.832071] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0573vm-test-run-scheduled-effects> buildbot # [    2.600919] systemd-vconsole-setup[181]: Configuration of first virtual console was skipped, ignoring remaining ones.574vm-test-run-scheduled-effects> buildbot # [    2.609473] systemd[1]: Finished Virtual Console Setup.575vm-test-run-scheduled-effects> buildbot # [    2.642937] systemd[1]: Found device /dev/disk/by-label/nixos.576vm-test-run-scheduled-effects> buildbot # [    2.645168] systemd[1]: Reached target Initrd Root Device.577vm-test-run-scheduled-effects> buildbot # [    2.891205] scsi host0: ata_piix578vm-test-run-scheduled-effects> buildbot # [    2.651114] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos...579vm-test-run-scheduled-effects> buildbot # [    2.905515] scsi host1: ata_piix580vm-test-run-scheduled-effects> buildbot # [    2.914274] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc1e0 irq 14 lpm-pol 0581vm-test-run-scheduled-effects> buildbot # [    2.921526] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc1e8 irq 15 lpm-pol 0582vm-test-run-scheduled-effects> buildbot # [    2.690430] systemd-fsck[195]: nixos: clean, 12/65536 files, 13019/262144 blocks583vm-test-run-scheduled-effects> buildbot # [    2.700531] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos.584vm-test-run-scheduled-effects> buildbot # [    2.708584] systemd[1]: Mounting /sysroot...585vm-test-run-scheduled-effects> buildbot # [    2.987065] usb 1-1: new full-speed USB device number 2 using uhci_hcd586vm-test-run-scheduled-effects> buildbot # [    3.083529] ata2: found unknown device (class 0)587vm-test-run-scheduled-effects> buildbot # [    3.089259] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100588vm-test-run-scheduled-effects> buildbot # [    3.097955] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.5+ PQ: 0 ANSI: 5589vm-test-run-scheduled-effects> buildbot # [    3.155248] usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00590vm-test-run-scheduled-effects> buildbot # [    3.157289] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=10591vm-test-run-scheduled-effects> buildbot # [    3.165027] usb 1-1: Product: QEMU USB Tablet592vm-test-run-scheduled-effects> buildbot # [    3.170029] usb 1-1: Manufacturer: QEMU593vm-test-run-scheduled-effects> buildbot # [    3.171272] usb 1-1: SerialNumber: 28754-0000:00:01.2-1594vm-test-run-scheduled-effects> buildbot # [    3.186189] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray595vm-test-run-scheduled-effects> buildbot # [    3.214024] cdrom: Uniform CD-ROM driver Revision: 3.20596vm-test-run-scheduled-effects> buildbot # [    3.226244] hid: raw HID events driver (C) Jiri Kosina597vm-test-run-scheduled-effects> buildbot # [    3.245360] EXT4-fs (vda): mounted filesystem c514fb58-d4de-4825-ac37-a7ca3e1ef2fb r/w with ordered data mode. Quota mode: none.598vm-test-run-scheduled-effects> buildbot # [    3.010964] systemd[1]: Mounted /sysroot.599vm-test-run-scheduled-effects> buildbot # [    3.012709] systemd[1]: Reached target Initrd Root File System.600vm-test-run-scheduled-effects> buildbot # [    3.263427] usbcore: registered new interface driver usbhid601vm-test-run-scheduled-effects> buildbot # [    3.022120] systemd[1]: Starting Mountpoints Configured in the Real Root...602vm-test-run-scheduled-effects> buildbot # [    3.273258] usbhid: USB HID core driver603vm-test-run-scheduled-effects> buildbot # [    3.288386] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input2604vm-test-run-scheduled-effects> buildbot # [    3.049286] systemd-sysroot-fstab-check[209]: /sysroot should be mounted in the initrd, will request daemon-reload.605vm-test-run-scheduled-effects> buildbot # [    3.053109] systemd[1]: Reload requested from client PID 209 ('systemd-sysroot') (unit initrd-parse-etc.service)...606vm-test-run-scheduled-effects> buildbot # [    3.055950] systemd[1]: Reloading...607vm-test-run-scheduled-effects> buildbot # [    3.312136] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:01.2-1/input0608vm-test-run-scheduled-effects> buildbot # [    3.321888] systemd[1]: Reloading finished in 269 ms.609vm-test-run-scheduled-effects> buildbot # [    3.338116] systemd-sysroot-fstab-check[209]: Requesting initrd-fs.target/start/replace...610vm-test-run-scheduled-effects> buildbot # [    3.392303] systemd-sysroot-fstab-check[209]: Requesting swap.target/start/replace...611vm-test-run-scheduled-effects> buildbot # [    3.400181] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio612vm-test-run-scheduled-effects> buildbot # [    3.403817] systemd[1]: initrd-parse-etc.service: Deactivated successfully.613vm-test-run-scheduled-effects> buildbot # [    3.407406] systemd[1]: Finished Mountpoints Configured in the Real Root.614vm-test-run-scheduled-effects> buildbot # [    3.410298] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies.615vm-test-run-scheduled-effects> buildbot # [    3.665264] systemd[1]: Mounting /sysroot/nix/.ro-store...616vm-test-run-scheduled-effects> buildbot # [    3.681532] systemd[1]: Mounting /sysroot/nix/.rw-store...617vm-test-run-scheduled-effects> buildbot # [    3.699233] systemd[1]: Mounting /sysroot/run...618vm-test-run-scheduled-effects> buildbot # [    3.717550] systemd[1]: Mounting /sysroot/tmp/shared...619vm-test-run-scheduled-effects> buildbot # [    3.733048] systemd[1]: Mounting /sysroot/tmp/xchg...620vm-test-run-scheduled-effects> buildbot # [    3.987520] 9p: Installing v9fs 9p2000 file system support621vm-test-run-scheduled-effects> buildbot # [    3.767332] systemd[1]: Mounted /sysroot/nix/.ro-store.622vm-test-run-scheduled-effects> buildbot # [    3.769352] systemd[1]: Mounted /sysroot/nix/.rw-store.623vm-test-run-scheduled-effects> buildbot # [    3.772261] systemd[1]: Mounted /sysroot/run.624vm-test-run-scheduled-effects> buildbot # [    3.773550] systemd[1]: Mounted /sysroot/tmp/shared.625vm-test-run-scheduled-effects> buildbot # [    3.780356] systemd[1]: Mounted /sysroot/tmp/xchg.626vm-test-run-scheduled-effects> buildbot # [    3.785673] systemd[1]: Starting rw-sysroot-nix-store.service...627vm-test-run-scheduled-effects> buildbot # [    3.798125] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.628vm-test-run-scheduled-effects> buildbot # [    3.801844] systemd[1]: Finished rw-sysroot-nix-store.service.629vm-test-run-scheduled-effects> buildbot # [    3.808317] systemd[1]: Mounting /sysroot/nix/store...630vm-test-run-scheduled-effects> buildbot # [    3.830389] systemd[1]: Mounted /sysroot/nix/store.631vm-test-run-scheduled-effects> buildbot # [    3.832641] systemd[1]: Reached target Initrd File Systems.632vm-test-run-scheduled-effects> buildbot # [    3.836958] systemd[1]: Starting Find NixOS closure...633vm-test-run-scheduled-effects> buildbot # [    3.841949] systemd[1]: Starting Create Volatile Files and Directories in the Real Root...634vm-test-run-scheduled-effects> buildbot # [    3.865766] systemd[1]: Finished Create Volatile Files and Directories in the Real Root.635vm-test-run-scheduled-effects> buildbot # [    3.875164] systemd[1]: Finished Find NixOS closure.636vm-test-run-scheduled-effects> buildbot # [    3.877356] systemd[1]: Reached target Initrd Default Target.637vm-test-run-scheduled-effects> buildbot # [    3.881354] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...638vm-test-run-scheduled-effects> buildbot # [    3.897417] systemd[1]: Stopped target Initrd Default Target.639vm-test-run-scheduled-effects> buildbot # [    3.899423] systemd[1]: Stopped target Basic System.640vm-test-run-scheduled-effects> buildbot # [    3.902226] systemd[1]: Stopped target Initrd Root Device.641vm-test-run-scheduled-effects> buildbot # [    3.903783] systemd[1]: Stopped target Path Units.642vm-test-run-scheduled-effects> buildbot # [    3.905398] systemd[1]: systemd-ask-password-console.path: Deactivated successfully.643vm-test-run-scheduled-effects> buildbot # [    3.907407] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.644vm-test-run-scheduled-effects> buildbot # [    3.909444] systemd[1]: Stopped target Slice Units.645vm-test-run-scheduled-effects> buildbot # [    3.911693] systemd[1]: Stopped target Socket Units.646vm-test-run-scheduled-effects> buildbot # [    3.914222] systemd[1]: Stopped target System Initialization.647vm-test-run-scheduled-effects> buildbot # [    3.916587] systemd[1]: Stopped target Swaps.648vm-test-run-scheduled-effects> buildbot # [    3.917955] systemd[1]: Stopped target Timer Units.649vm-test-run-scheduled-effects> buildbot # [    3.920246] systemd[1]: dbus.socket: Deactivated successfully.650vm-test-run-scheduled-effects> buildbot # [    3.922000] systemd[1]: Closed D-Bus System Message Bus Socket.651vm-test-run-scheduled-effects> buildbot # [    3.924099] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully.652vm-test-run-scheduled-effects> buildbot # [    3.926479] systemd[1]: Stopped Find NixOS closure.653vm-test-run-scheduled-effects> buildbot # [    3.930276] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio654vm-test-run-scheduled-effects> buildbot # [    3.936304] systemd[1]: Starting rw-sysroot-nix-store.service...655vm-test-run-scheduled-effects> buildbot # [    3.938321] systemd[1]: systemd-sysctl.service: Deactivated successfully.656vm-test-run-scheduled-effects> buildbot # [    3.941241] systemd[1]: Stopped Apply Kernel Variables.657vm-test-run-scheduled-effects> buildbot # [    3.946717] systemd[1]: systemd-modules-load.service: Deactivated successfully.658vm-test-run-scheduled-effects> buildbot # [    3.949234] systemd[1]: Stopped Load Kernel Modules.659vm-test-run-scheduled-effects> buildbot # [    3.954376] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully.660vm-test-run-scheduled-effects> buildbot # [    3.956524] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root.661vm-test-run-scheduled-effects> buildbot # [    3.963680] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.662vm-test-run-scheduled-effects> buildbot # [    3.966390] systemd[1]: Stopped Create System Files and Directories.663vm-test-run-scheduled-effects> buildbot # [    3.970438] systemd[1]: Stopped target Local File Systems.664vm-test-run-scheduled-effects> buildbot # [    3.972509] systemd[1]: Stopped target Preparation for Local File Systems.665vm-test-run-scheduled-effects> buildbot # [    3.974892] systemd[1]: systemd-udev-trigger.service: Deactivated successfully.666vm-test-run-scheduled-effects> buildbot # [    3.977229] systemd[1]: Stopped Coldplug All udev Devices.667vm-test-run-scheduled-effects> buildbot # [    3.981152] systemd[1]: Stopping Rule-based Manager for Device Events and Files...668vm-test-run-scheduled-effects> buildbot # [    3.983966] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.669vm-test-run-scheduled-effects> buildbot # [    3.987109] systemd[1]: Stopped Virtual Console Setup.670vm-test-run-scheduled-effects> buildbot # [    3.995926] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.671vm-test-run-scheduled-effects> buildbot # [    4.000455] systemd[1]: Finished rw-sysroot-nix-store.service.672vm-test-run-scheduled-effects> buildbot # [    4.007147] systemd[1]: systemd-udevd.service: Deactivated successfully.673vm-test-run-scheduled-effects> buildbot # [    4.009983] systemd[1]: Stopped Rule-based Manager for Device Events and Files.674vm-test-run-scheduled-effects> buildbot # [    4.018063] systemd[1]: initrd-cleanup.service: Deactivated successfully.675vm-test-run-scheduled-effects> buildbot # [    4.022788] systemd[1]: Finished Cleaning Up and Shutting Down Daemons.676vm-test-run-scheduled-effects> buildbot # [    4.029231] systemd[1]: systemd-udevd-control.socket: Deactivated successfully.677vm-test-run-scheduled-effects> buildbot # [    4.031349] systemd[1]: Closed udev Control Socket.678vm-test-run-scheduled-effects> buildbot # [    4.036941] systemd[1]: Starting Cleanup udev Database...679vm-test-run-scheduled-effects> buildbot # [    4.038757] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.680vm-test-run-scheduled-effects> buildbot # [    4.042198] systemd[1]: Stopped Create Static Device Nodes in /dev.681vm-test-run-scheduled-effects> buildbot # [    4.049589] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully.682vm-test-run-scheduled-effects> buildbot # [    4.051728] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully.683vm-test-run-scheduled-effects> buildbot # [    4.054981] systemd[1]: kmod-static-nodes.service: Deactivated successfully.684vm-test-run-scheduled-effects> buildbot # [    4.058177] systemd[1]: Stopped Create List of Static Device Nodes.685vm-test-run-scheduled-effects> buildbot # [    4.073082] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.686vm-test-run-scheduled-effects> buildbot # [    4.076818] systemd[1]: Finished Cleanup udev Database.687vm-test-run-scheduled-effects> buildbot # [    4.081386] systemd[1]: Reached target Switch Root.688vm-test-run-scheduled-effects> buildbot # [    4.085123] systemd[1]: Starting NixOS Activation...689vm-test-run-scheduled-effects> buildbot # [    4.274946] initrd-nixos-activation-start[497]: booting system configuration /nix/store/nswbpy9j7m34fi0s5bq3b34fk13smbw6-nixos-system-buildbot-test690vm-test-run-scheduled-effects> buildbot # [    4.349571] initrd-nixos-activation-start[497]: running activation script...691vm-test-run-scheduled-effects> buildbot # [    4.844264] initrd-nixos-activation-start[520]: setting up /etc...692vm-test-run-scheduled-effects> buildbot # [    5.154503] systemd[1]: initrd-nixos-activation.service: Deactivated successfully.693vm-test-run-scheduled-effects> buildbot # [    5.158727] systemd[1]: Finished NixOS Activation.694vm-test-run-scheduled-effects> buildbot # [    5.164804] systemd[1]: Starting Switch Root...695vm-test-run-scheduled-effects> buildbot # [    5.181162] systemd[1]: Switching root.696vm-test-run-scheduled-effects> buildbot # [    5.578589] systemd-journald[125]: Received SIGTERM from PID 1 (systemd).697vm-test-run-scheduled-effects> buildbot # [    5.745768] NET: Registered PF_VSOCK protocol family698vm-test-run-scheduled-effects> buildbot # [    6.140960] systemd[1]: systemd 260.1 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -BTF -XKBCOMMON +UTMP +LIBARCHIVE)699vm-test-run-scheduled-effects> buildbot # [    6.157751] systemd[1]: Detected virtualization kvm.700vm-test-run-scheduled-effects> buildbot # [    6.161146] systemd[1]: Detected architecture x86-64.701vm-test-run-scheduled-effects> buildbot # [    6.164445] systemd[1]: Detected first boot.702vm-test-run-scheduled-effects> buildbot # [    6.173883] systemd[1]: Initializing machine ID from random generator.703vm-test-run-scheduled-effects> buildbot # [    6.433766] systemd[1]: bpf-restrict-fs: LSM BPF program attached704vm-test-run-scheduled-effects> buildbot # [    6.575276] systemd[1]: Applying preset policy.705vm-test-run-scheduled-effects> buildbot # [    7.162539] systemd[1]: Populated /etc with preset unit settings.706vm-test-run-scheduled-effects> buildbot # [    7.769139] systemd[1]: initrd-switch-root.service: Deactivated successfully.707vm-test-run-scheduled-effects> buildbot # [    7.771776] systemd[1]: Stopped initrd-switch-root.service.708vm-test-run-scheduled-effects> buildbot # [    7.775487] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.709vm-test-run-scheduled-effects> buildbot # [    7.778684] systemd[1]: Created slice Slice /system/getty.710vm-test-run-scheduled-effects> buildbot # [    7.780824] systemd[1]: Created slice User and Session Slice.711vm-test-run-scheduled-effects> buildbot # [    7.782448] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.712vm-test-run-scheduled-effects> buildbot # [    7.784532] systemd[1]: Started Forward Password Requests to Wall Directory Watch.713vm-test-run-scheduled-effects> buildbot # [    7.786745] systemd[1]: Expecting device /dev/hvc0...714vm-test-run-scheduled-effects> buildbot # [    7.788162] systemd[1]: Expecting device /dev/ttyS0...715vm-test-run-scheduled-effects> buildbot # [    7.789537] systemd[1]: Reached target Local Encrypted Volumes.716vm-test-run-scheduled-effects> buildbot # [    7.791090] systemd[1]: Stopped target initrd-fs.target.717vm-test-run-scheduled-effects> buildbot # [    7.792447] systemd[1]: Stopped target initrd-root-fs.target.718vm-test-run-scheduled-effects> buildbot # [    7.793934] systemd[1]: Stopped target initrd-switch-root.target.719vm-test-run-scheduled-effects> buildbot # [    7.795515] systemd[1]: Reached target Virtual Machines and Containers.720vm-test-run-scheduled-effects> buildbot # [    7.797186] systemd[1]: Reached target Path Units.721vm-test-run-scheduled-effects> buildbot # [    7.798483] systemd[1]: Reached target Remote File Systems.722vm-test-run-scheduled-effects> buildbot # [    7.799949] systemd[1]: Reached target Slice Units.723vm-test-run-scheduled-effects> buildbot # [    7.801310] systemd[1]: Reached target Swaps.724vm-test-run-scheduled-effects> buildbot # [    7.807483] systemd[1]: Listening on Process Core Dump Socket.725vm-test-run-scheduled-effects> buildbot # [    7.812123] systemd[1]: Listening on Credential Encryption/Decryption.726vm-test-run-scheduled-effects> buildbot # [    7.817790] systemd[1]: Starting Journal Log Access Socket...727vm-test-run-scheduled-effects> buildbot # [    7.820352] systemd[1]: Listening on Journal Audit Socket.728vm-test-run-scheduled-effects> buildbot # [    7.822366] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.729vm-test-run-scheduled-effects> buildbot # [    7.824505] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki730vm-test-run-scheduled-effects> buildbot # [    7.827382] systemd[1]: Listening on udev Control Socket.731vm-test-run-scheduled-effects> buildbot # [    7.833281] systemd[1]: Mounting Huge Pages File System...732vm-test-run-scheduled-effects> buildbot # [    7.837722] systemd[1]: Mounting POSIX Message Queue File System...733vm-test-run-scheduled-effects> buildbot # [    7.842858] systemd[1]: Mounting Kernel Debug File System...734vm-test-run-scheduled-effects> buildbot # [    7.852945] systemd[1]: Mounting Kernel Trace File System...735vm-test-run-scheduled-effects> buildbot # [    7.862493] systemd[1]: Starting Create List of Static Device Nodes...736vm-test-run-scheduled-effects> buildbot # [    7.865773] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio737vm-test-run-scheduled-effects> buildbot # [    7.877212] systemd[1]: Starting Load Kernel Module configfs...738vm-test-run-scheduled-effects> buildbot # [    7.880344] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm739vm-test-run-scheduled-effects> buildbot # [    7.883694] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore740vm-test-run-scheduled-effects> buildbot # [    7.886868] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse741vm-test-run-scheduled-effects> buildbot # [    7.899083] systemd[1]: Mounting FUSE Control File System...742vm-test-run-scheduled-effects> buildbot # [    7.901438] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67743vm-test-run-scheduled-effects> buildbot # [    7.940729] systemd[1]: Starting Journal Service...744vm-test-run-scheduled-effects> buildbot # [    7.959233] systemd[1]: Starting Load Kernel Modules...745vm-test-run-scheduled-effects> buildbot # [    7.974048] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...746vm-test-run-scheduled-effects> buildbot # [    7.982600] systemd[1]: Starting Remount Root and Kernel File Systems...747vm-test-run-scheduled-effects> buildbot # [    7.988172] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki748vm-test-run-scheduled-effects> buildbot # [    8.010242] systemd[1]: Starting Coldplug All udev Devices...749vm-test-run-scheduled-effects> buildbot # [    8.034594] systemd-journald[730]: Collecting audit messages is enabled.750vm-test-run-scheduled-effects> buildbot # [    8.036404] systemd[1]: Listening on Journal Log Access Socket.751vm-test-run-scheduled-effects> buildbot # [    8.047029] systemd[1]: Mounted Huge Pages File System.752vm-test-run-scheduled-effects> buildbot # [    8.055284] systemd[1]: Mounted POSIX Message Queue File System.753vm-test-run-scheduled-effects> buildbot # [    8.060382] loop: module loaded754vm-test-run-scheduled-effects> buildbot # [    8.064776] systemd[1]: Mounted Kernel Debug File System.755vm-test-run-scheduled-effects> buildbot # [    8.071099] EXT4-fs (vda): re-mounted c514fb58-d4de-4825-ac37-a7ca3e1ef2fb.756vm-test-run-scheduled-effects> buildbot # [    8.074334] systemd[1]: Mounted Kernel Trace File System.757vm-test-run-scheduled-effects> buildbot # [    8.090102] systemd[1]: Finished Create List of Static Device Nodes.758vm-test-run-scheduled-effects> buildbot # [    8.097806] systemd[1]: Started Journal Service.759vm-test-run-scheduled-effects> buildbot # [    7.856112] systemd[1]: Queued start job for default target Multi-User System.760vm-test-run-scheduled-effects> buildbot # [    7.858540] systemd[1]: systemd-journald.service: Deactivated successfully.761vm-test-run-scheduled-effects> buildbot # [    7.864839] systemd-modules-load[731]: Inserted module 'loop'762vm-test-run-scheduled-effects> buildbot # [    7.871193] systemd[1]: modprobe@configfs.service: Deactivated successfully.763vm-test-run-scheduled-effects> buildbot # [    7.876932] systemd-modules-load[731]: Inserted module 'tls'764vm-test-run-scheduled-effects> buildbot # [    7.881459] systemd[1]: Finished Load Kernel Module configfs.765vm-test-run-scheduled-effects> buildbot # [    7.885629] systemd[1]: Mounted FUSE Control File System.766vm-test-run-scheduled-effects> buildbot # [    7.890598] systemd[1]: Finished Remount Root and Kernel File Systems.767vm-test-run-scheduled-effects> buildbot # [    7.897124] systemd[1]: Finished Load Kernel Modules.768vm-test-run-scheduled-effects> buildbot # [    7.920816] systemd[1]: Mounting Kernel Configuration File System...769vm-test-run-scheduled-effects> buildbot # [    7.931466] systemd[1]: Starting Flush Journal to Persistent Storage...770vm-test-run-scheduled-effects> buildbot # [    7.933580] systemd-oomd[733]: No swap; memory pressure usage will be degraded771vm-test-run-scheduled-effects> buildbot # [    7.937386] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore772vm-test-run-scheduled-effects> buildbot # [    7.943254] systemd[1]: Starting Load/Save OS Random Seed...773vm-test-run-scheduled-effects> buildbot # [    7.963056] systemd[1]: Starting Apply Kernel Variables...774vm-test-run-scheduled-effects> buildbot # [    7.972991] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...775vm-test-run-scheduled-effects> buildbot # [    7.975383] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki776vm-test-run-scheduled-effects> buildbot # [    7.984111] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.777vm-test-run-scheduled-effects> buildbot # [    8.285636] systemd-journald[730]: Received client request to flush runtime journal.778vm-test-run-scheduled-effects> buildbot # [    8.208498] systemd[1]: Finished Load/Save OS Random Seed.779vm-test-run-scheduled-effects> buildbot # [    8.213387] systemd[1]: Mounted Kernel Configuration File System.780vm-test-run-scheduled-effects> buildbot # [    8.217126] systemd[1]: Reached target First Boot Complete.781vm-test-run-scheduled-effects> buildbot # [    8.218874] systemd[1]: Finished Apply Kernel Variables.782vm-test-run-scheduled-effects> buildbot # [    8.220408] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.783vm-test-run-scheduled-effects> buildbot # [    8.223293] systemd[1]: Starting Create Static Device Nodes in /dev...784vm-test-run-scheduled-effects> buildbot # [    8.225883] systemd[1]: Finished Flush Journal to Persistent Storage.785vm-test-run-scheduled-effects> buildbot # [    8.283196] systemd[1]: Finished Create Static Device Nodes in /dev.786vm-test-run-scheduled-effects> buildbot # [    8.285167] systemd[1]: Reached target Preparation for Local File Systems.787vm-test-run-scheduled-effects> buildbot # [    8.293294] systemd[1]: Starting Rule-based Manager for Device Events and Files...788vm-test-run-scheduled-effects> buildbot # [    8.334803] systemd[1]: Finished Coldplug All udev Devices.789vm-test-run-scheduled-effects> buildbot # [    8.388397] systemd-udevd[762]: Using default interface naming scheme 'v260'.790vm-test-run-scheduled-effects> buildbot # [    8.516610] systemd[1]: Started Rule-based Manager for Device Events and Files.791vm-test-run-scheduled-effects> buildbot # [    8.530324] systemd[1]: Mounting /run/wrappers...792vm-test-run-scheduled-effects> buildbot # [    8.578129] systemd[1]: Mounted /run/wrappers.793vm-test-run-scheduled-effects> buildbot # [    8.579562] systemd[1]: Reached target Local File Systems.794vm-test-run-scheduled-effects> buildbot # [    8.585113] systemd[1]: Listening on Boot Loader Control Service Socket.795vm-test-run-scheduled-effects> buildbot # [    8.591098] systemd[1]: Starting register-nix-paths.service...796vm-test-run-scheduled-effects> buildbot # [    8.597222] systemd[1]: Starting Create SUID/SGID Wrappers...797vm-test-run-scheduled-effects> buildbot # [    8.600100] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.798vm-test-run-scheduled-effects> buildbot # [    8.608114] systemd[1]: Starting Save Transient machine-id to Disk...799vm-test-run-scheduled-effects> buildbot # [    8.620513] systemd[1]: Starting Create System Files and Directories...800vm-test-run-scheduled-effects> buildbot # [    8.698789] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.801vm-test-run-scheduled-effects> buildbot # [    8.709674] systemd[1]: Finished Save Transient machine-id to Disk.802vm-test-run-scheduled-effects> buildbot # [    8.785354] systemd[1]: Finished Create System Files and Directories.803vm-test-run-scheduled-effects> buildbot # [    8.796843] systemd[1]: Starting Rebuild Journal Catalog...804vm-test-run-scheduled-effects> buildbot # [    8.805418] systemd[1]: Starting Record System Boot/Shutdown in UTMP...805vm-test-run-scheduled-effects> buildbot # [    8.904266] systemd[1]: Finished Record System Boot/Shutdown in UTMP.806vm-test-run-scheduled-effects> buildbot # [    8.929163] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse807vm-test-run-scheduled-effects> buildbot # [    8.959851] systemd[1]: Finished Rebuild Journal Catalog.808vm-test-run-scheduled-effects> buildbot # [    8.968938] systemd[1]: Starting Update is Completed...809vm-test-run-scheduled-effects> buildbot # [    9.029751] systemd[1]: Finished Update is Completed.810vm-test-run-scheduled-effects> buildbot # [    9.144641] systemd[1]: Condition check resulted in /dev/hvc0 being skipped.811vm-test-run-scheduled-effects> buildbot # [    9.202331] systemd[1]: Condition check resulted in /dev/ttyS0 being skipped.812vm-test-run-scheduled-effects> buildbot # [    9.251449] (udev-worker)[780]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.813vm-test-run-scheduled-effects> buildbot # [    9.258986] (udev-worker)[780]: Network interface NamePolicy= disabled on kernel command line.814vm-test-run-scheduled-effects> buildbot # [    9.263649] (udev-worker)[789]: Network interface NamePolicy= disabled on kernel command line.815vm-test-run-scheduled-effects> buildbot # [    9.386995] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.816vm-test-run-scheduled-effects> buildbot # [    9.392336] systemd[1]: Finished Create SUID/SGID Wrappers.817vm-test-run-scheduled-effects> buildbot # [    9.453576] systemd[1]: Condition check resulted in Virtio network device being skipped.818vm-test-run-scheduled-effects> buildbot # [    9.456453] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore819vm-test-run-scheduled-effects> buildbot # [    9.465175] systemd[1]: Starting Create SUID/SGID Wrappers...820vm-test-run-scheduled-effects> buildbot # [    9.467233] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.821vm-test-run-scheduled-effects> buildbot # [    9.469997] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67822vm-test-run-scheduled-effects> buildbot # [    9.475113] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore823vm-test-run-scheduled-effects> buildbot # [    9.477979] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki824vm-test-run-scheduled-effects> buildbot # [    9.481736] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki825vm-test-run-scheduled-effects> buildbot # [    9.697139] systemd[1]: Finished register-nix-paths.service.826vm-test-run-scheduled-effects> buildbot # [    9.978344] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3827vm-test-run-scheduled-effects> buildbot # [    9.984039] mousedev: PS/2 mouse device common for all mice828vm-test-run-scheduled-effects> buildbot # [   10.007253] ACPI: button: Power Button [PWRF]829vm-test-run-scheduled-effects> buildbot # [   10.036431] rtc_cmos 00:05: RTC can wake from S4830vm-test-run-scheduled-effects> buildbot # [   10.060031] parport_pc 00:03: reported by Plug and Play ACPI831vm-test-run-scheduled-effects> buildbot # [   10.065679] Floppy drive(s): fd0 is 2.88M AMI BIOS832vm-test-run-scheduled-effects> buildbot # [   10.077762] rtc_cmos 00:05: registered as rtc0833vm-test-run-scheduled-effects> buildbot # [   10.079376] rtc_cmos 00:05: setting system clock to 2026-06-28T06:13:38 UTC (1782627218)834vm-test-run-scheduled-effects> buildbot # [   10.081668] systemd-journald[730]: Time jumped backwards, rotating.835vm-test-run-scheduled-effects> buildbot # [   10.088161] parport0: PC-style at 0x378, irq 7 [PCSPP(,...)]836vm-test-run-scheduled-effects> buildbot # [   10.115861] FDC 0 is a S82078B837vm-test-run-scheduled-effects> buildbot # [   10.117207] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs838vm-test-run-scheduled-effects> buildbot # [   10.146127] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0839vm-test-run-scheduled-effects> buildbot # [   10.175780] i2c i2c-0: Memory type 0x07 not supported yet, not instantiating SPD840vm-test-run-scheduled-effects> buildbot # [   10.179947] bochs-drm 0000:00:02.0: vgaarb: deactivate vga console841vm-test-run-scheduled-effects> buildbot # [   10.215640] input: QEMU Virtio Keyboard as /devices/pci0000:00/0000:00:0a.0/virtio7/input/input4842vm-test-run-scheduled-effects> buildbot # [   10.266637] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input6843vm-test-run-scheduled-effects> buildbot # [   10.267063] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input5844vm-test-run-scheduled-effects> buildbot # [   10.323552] Console: switching to colour dummy device 80x25845vm-test-run-scheduled-effects> buildbot # [   10.385258] [drm] Found bochs VGA, ID 0xb0c5.846vm-test-run-scheduled-effects> buildbot # [   10.385260] [drm] Framebuffer size 16384 kB @ 0xfd000000, mmio @ 0xfebd0000.847vm-test-run-scheduled-effects> buildbot # [   10.407116] bochs-drm 0000:00:02.0: [drm] Registered 1 planes with drm panic848vm-test-run-scheduled-effects> buildbot # [   10.166253] systemd[1]: Starting Virtual Console Setup...849vm-test-run-scheduled-effects> buildbot # [   10.437706] [drm] Initialized bochs-drm 1.0.0 for 0000:00:02.0 on minor 0850vm-test-run-scheduled-effects> buildbot # [   10.244737] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.851vm-test-run-scheduled-effects> buildbot # [   10.249238] systemd[1]: Finished Create SUID/SGID Wrappers.852vm-test-run-scheduled-effects> buildbot # [   10.521528] ppdev: user-space parallel port driver853vm-test-run-scheduled-effects> buildbot # [   10.525424] fbcon: bochs-drmdrmfb (fb0) is primary device854vm-test-run-scheduled-effects> buildbot # [   10.578568] Console: switching to colour frame buffer device 160x50855vm-test-run-scheduled-effects> buildbot # [   10.631057] bochs-drm 0000:00:02.0: [drm] fb0: bochs-drmdrmfb frame buffer device856vm-test-run-scheduled-effects> buildbot # [   10.393735] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.857vm-test-run-scheduled-effects> buildbot # [   10.399107] systemd[1]: Stopped Virtual Console Setup.858vm-test-run-scheduled-effects> buildbot # [   10.413755] systemd[1]: Starting Virtual Console Setup...859vm-test-run-scheduled-effects> buildbot # [   10.726131] kvm_amd: TSC scaling supported860vm-test-run-scheduled-effects> buildbot # [   10.726929] kvm_amd: Nested Virtualization enabled861vm-test-run-scheduled-effects> buildbot # [   10.728343] kvm_amd: Nested Paging enabled862vm-test-run-scheduled-effects> buildbot # [   10.729425] kvm_amd: LBR virtualization supported863vm-test-run-scheduled-effects> buildbot # [   10.730566] kvm_amd: Virtual VMLOAD VMSAVE supported864vm-test-run-scheduled-effects> buildbot # [   10.731905] kvm_amd: Virtual GIF supported865vm-test-run-scheduled-effects> buildbot # [   10.732936] kvm_amd: Virtual NMI enabled866vm-test-run-scheduled-effects> buildbot # [   10.780411] EDAC MC: Ver: 3.0.0867vm-test-run-scheduled-effects> buildbot # [   11.063704] systemd-vconsole-setup[939]: Configuration of first virtual console was skipped, ignoring remaining ones.868vm-test-run-scheduled-effects> buildbot # [   11.070119] systemd[1]: Finished Virtual Console Setup.869vm-test-run-scheduled-effects> buildbot # [   11.072323] systemd[1]: Reached target System Initialization.870vm-test-run-scheduled-effects> buildbot # [   11.075203] systemd[1]: Started Discard unused filesystem blocks once a week.871vm-test-run-scheduled-effects> buildbot # [   11.077751] systemd[1]: Started Daily Cleanup of Temporary Directories.872vm-test-run-scheduled-effects> buildbot # [   11.079663] systemd[1]: Reached target Timer Units.873vm-test-run-scheduled-effects> buildbot # [   11.081824] systemd[1]: Listening on D-Bus System Message Bus Socket.874vm-test-run-scheduled-effects> buildbot # [   11.083676] systemd[1]: Listening on Nix Daemon Socket.875vm-test-run-scheduled-effects> buildbot # [   11.086771] systemd[1]: Listening on OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local).876vm-test-run-scheduled-effects> buildbot # [   11.090094] systemd[1]: Listening on Hostname Service Socket.877vm-test-run-scheduled-effects> buildbot # [   11.091641] systemd[1]: Reached target Socket Units.878vm-test-run-scheduled-effects> buildbot # [   11.093117] systemd[1]: Reached target Basic System.879vm-test-run-scheduled-effects> buildbot # [   11.097260] systemd[1]: Started backdoor.service.880vm-test-run-scheduled-effects> buildbot # [   11.102121] systemd[1]: Starting Import lastlog data into lastlog2 database...881vm-test-run-scheduled-effects> buildbot # [   11.107118] systemd[1]: Starting Name Service Cache Daemon (nsncd)...882vm-test-run-scheduled-effects> buildbot # [   11.113495] systemd[1]: Starting Post-Boot Actions...883vm-test-run-scheduled-effects> buildbot # [   11.124122] systemd[1]: Started Reset console on configuration changes.884vm-test-run-scheduled-effects> buildbot # [   11.136340] systemd[1]: Starting resolvconf update...885vm-test-run-scheduled-effects> buildbot # [   11.139092] systemd[1]: SSH Host Keys Generation skipped, no trigger condition checks were met.886vm-test-run-scheduled-effects> buildbot # [   11.175494] systemd[1]: Starting D-Bus System Message Bus...887vm-test-run-scheduled-effects> buildbot # [   11.212884] systemd[1]: Finished Post-Boot Actions.888vm-test-run-scheduled-effects> buildbot # connecting to host...889vm-test-run-scheduled-effects> buildbot # [   11.238506] systemd[1]: Started Name Service Cache Daemon (nsncd).890vm-test-run-scheduled-effects> buildbot # [   11.240316] systemd[1]: Reached target Host and Network Name Lookups.891vm-test-run-scheduled-effects> buildbot # [   11.242005] systemd[1]: Reached target User and Group Name Lookups.892vm-test-run-scheduled-effects> buildbot # [   11.247254] nsncd[945]: Jun 28 06:13:39.900 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"893vm-test-run-scheduled-effects> buildbot # [   11.262728] systemd[1]: Starting User Login Management...894vm-test-run-scheduled-effects> buildbot # [   11.281602] systemd[1]: Finished Import lastlog data into lastlog2 database.895vm-test-run-scheduled-effects> buildbot: Guest shell says: b'Spawning backdoor root shell...\n'896vm-test-run-scheduled-effects> buildbot: connected to guest root shell897vm-test-run-scheduled-effects> buildbot: (connecting took 12.27 seconds)898vm-test-run-scheduled-effects> buildbot: (finished: waiting for the VM to finish booting, in 12.55 seconds)899vm-test-run-scheduled-effects> buildbot # [   11.393986] dbus-broker-launch[950]: Looking up NSS user entry for 'systemd-timesync'...900vm-test-run-scheduled-effects> buildbot # [   11.398892] systemd-logind[970]: New seat seat0.901vm-test-run-scheduled-effects> buildbot # [   11.405448] systemd-logind[970]: Watching system buttons on /dev/input/event2 (Power Button)902vm-test-run-scheduled-effects> buildbot # [   11.409708] systemd-logind[970]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)903vm-test-run-scheduled-effects> buildbot # [   11.413387] systemd-logind[970]: Watching system buttons on /dev/input/event0 (AT Translated Set 2 keyboard)904vm-test-run-scheduled-effects> buildbot # [   11.430945] systemd[1]: Started User Login Management.905vm-test-run-scheduled-effects> buildbot # [   11.444851] dbus-broker-launch[950]: NSS returned no entry for 'systemd-timesync'906vm-test-run-scheduled-effects> buildbot # [   11.448334] dbus-broker-launch[950]: Invalid user-name in /nix/store/gj08g20q1rhcg88153r5435b6klhhiyz-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"907vm-test-run-scheduled-effects> buildbot # [   11.452859] systemd[1]: Stopped target Host and Network Name Lookups.908vm-test-run-scheduled-effects> buildbot # [   11.455472] systemd[1]: Stopping Host and Network Name Lookups...909vm-test-run-scheduled-effects> buildbot # [   11.458340] systemd[1]: Stopped target User and Group Name Lookups.910vm-test-run-scheduled-effects> buildbot # [   11.461101] systemd[1]: Stopping User and Group Name Lookups...911vm-test-run-scheduled-effects> buildbot # [   11.465138] systemd[1]: Starting linger-users.service...912vm-test-run-scheduled-effects> buildbot # [   11.466687] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...913vm-test-run-scheduled-effects> buildbot # [   11.472934] systemd[1]: nscd.service: Deactivated successfully.914vm-test-run-scheduled-effects> buildbot # [   11.478205] systemd[1]: Stopped Name Service Cache Daemon (nsncd).915vm-test-run-scheduled-effects> buildbot # [   11.508695] systemd[1]: Starting Name Service Cache Daemon (nsncd)...916vm-test-run-scheduled-effects> buildbot # [   11.521777] systemd[1]: Started D-Bus System Message Bus.917vm-test-run-scheduled-effects> buildbot # [   11.565760] dbus-broker-launch[950]: Ready918vm-test-run-scheduled-effects> buildbot # [   11.571154] systemd[1]: linger-users.service: Deactivated successfully.919vm-test-run-scheduled-effects> buildbot # [   11.574631] systemd[1]: Finished linger-users.service.920vm-test-run-scheduled-effects> buildbot # [   11.604625] systemd[1]: Started Name Service Cache Daemon (nsncd).921vm-test-run-scheduled-effects> buildbot # [   11.607711] nsncd[1020]: Jun 28 06:13:40.271 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"922vm-test-run-scheduled-effects> buildbot # [   11.613129] systemd[1]: Reached target Host and Network Name Lookups.923vm-test-run-scheduled-effects> buildbot # [   11.615949] systemd[1]: Reached target User and Group Name Lookups.924vm-test-run-scheduled-effects> buildbot # [   11.641236] systemd[1]: Finished resolvconf update.925vm-test-run-scheduled-effects> buildbot # [   11.644583] systemd[1]: Reached target Preparation for Network.926vm-test-run-scheduled-effects> buildbot # [   11.650885] systemd[1]: Starting DHCP Client...927vm-test-run-scheduled-effects> buildbot # [   11.655638] systemd[1]: Starting Address configuration of eth1...928vm-test-run-scheduled-effects> buildbot # [   11.661715] systemd[1]: Starting Extra networking commands....929vm-test-run-scheduled-effects> buildbot # [   11.820244] network-addresses-eth1-start[1049]: adding address 192.168.1.1/24... done930vm-test-run-scheduled-effects> buildbot # [   11.843165] network-addresses-eth1-start[1049]: adding address 2001:db8:1::1/64... done931vm-test-run-scheduled-effects> buildbot # [   11.871766] systemd[1]: Finished Address configuration of eth1.932vm-test-run-scheduled-effects> buildbot # [   11.882800] dhcpcd[1067]: dhcpcd-10.3.2 starting933vm-test-run-scheduled-effects> buildbot # [   11.899832] dhcpcd[1114]: dev: loaded udev934vm-test-run-scheduled-effects> buildbot # [   11.910489] systemd[1]: Finished Extra networking commands..935vm-test-run-scheduled-effects> buildbot # [   11.914138] systemd[1]: Reached target Network.936vm-test-run-scheduled-effects> buildbot # [   11.920171] systemd[1]: Starting Nginx Web Server...937vm-test-run-scheduled-effects> buildbot # [   11.926385] systemd[1]: Starting PostgreSQL Server...938vm-test-run-scheduled-effects> buildbot # [   11.932107] systemd[1]: Starting SSH Daemon...939vm-test-run-scheduled-effects> buildbot # [   12.185583] 8021q: 802.1Q VLAN Support v1.8940vm-test-run-scheduled-effects> buildbot # [   11.944214] systemd[1]: Starting Permit User Sessions...941vm-test-run-scheduled-effects> buildbot # [   12.192038] 8021q: adding VLAN 0 to HW filter on device eth1942vm-test-run-scheduled-effects> buildbot # [   12.023330] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.943vm-test-run-scheduled-effects> buildbot # [   12.043169] systemd[1]: Finished Permit User Sessions.944vm-test-run-scheduled-effects> buildbot # [   12.056595] systemd[1]: Started Getty on tty1.945vm-test-run-scheduled-effects> buildbot # [   12.057981] systemd[1]: Reached target Login Prompts.946vm-test-run-scheduled-effects> buildbot # [   12.090902] sshd[1121]: Server listening on 0.0.0.0 port 22.947vm-test-run-scheduled-effects> buildbot # [   12.097072] sshd[1121]: Server listening on :: port 22.948vm-test-run-scheduled-effects> buildbot # [   12.098781] systemd[1]: Started SSH Daemon.949vm-test-run-scheduled-effects> buildbot # [   12.106752] systemd[1]: Starting Setup git test repository with scheduled effects...950vm-test-run-scheduled-effects> buildbot # [   12.409735] cfg80211: Loading compiled-in X.509 certificates for regulatory database951vm-test-run-scheduled-effects> buildbot # [   12.455966] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'952vm-test-run-scheduled-effects> buildbot # [   12.457432] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'953vm-test-run-scheduled-effects> buildbot # [   12.464087] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2954vm-test-run-scheduled-effects> buildbot # [   12.465772] cfg80211: failed to load regulatory.db955vm-test-run-scheduled-effects> buildbot # [   12.300869] setup-git-repo-start[1140]: hint: Using 'master' as the name for the initial branch. This default branch name956vm-test-run-scheduled-effects> buildbot # [   12.304274] setup-git-repo-start[1140]: hint: will change to "main" in Git 3.0. To configure the initial branch name957vm-test-run-scheduled-effects> buildbot # [   12.307852] setup-git-repo-start[1140]: hint: to use in all of your new repositories, which will suppress this warning,958vm-test-run-scheduled-effects> buildbot # [   12.312176] setup-git-repo-start[1140]: hint: call:959vm-test-run-scheduled-effects> buildbot # [   12.313633] setup-git-repo-start[1140]: hint:960vm-test-run-scheduled-effects> buildbot # [   12.315162] setup-git-repo-start[1140]: hint: 	git config --global init.defaultBranch <name>961vm-test-run-scheduled-effects> buildbot # [   12.318921] setup-git-repo-start[1140]: hint:962vm-test-run-scheduled-effects> buildbot # [   12.321262] setup-git-repo-start[1140]: hint: Names commonly chosen instead of 'master' are 'main', 'trunk' and963vm-test-run-scheduled-effects> buildbot # [   12.323889] setup-git-repo-start[1140]: hint: 'development'. The just-created branch can be renamed via this command:964vm-test-run-scheduled-effects> buildbot # [   12.326867] setup-git-repo-start[1140]: hint:965vm-test-run-scheduled-effects> buildbot # [   12.328398] setup-git-repo-start[1140]: hint: 	git branch -m <name>966vm-test-run-scheduled-effects> buildbot # [   12.331568] setup-git-repo-start[1140]: hint:967vm-test-run-scheduled-effects> buildbot # [   12.334235] setup-git-repo-start[1140]: hint: Disable this message with "git config set advice.defaultBranchName false"968vm-test-run-scheduled-effects> buildbot # [   12.337718] setup-git-repo-start[1140]: Initialized empty Git repository in /srv/repos/test-flake.git/969vm-test-run-scheduled-effects> buildbot # [   12.591745] 8021q: adding VLAN 0 to HW filter on device eth0970vm-test-run-scheduled-effects> buildbot # [   12.351203] dhcpcd[1114]: eth0: waiting for carrier971vm-test-run-scheduled-effects> buildbot # [   12.354748] dhcpcd[1114]: eth0: carrier acquired972vm-test-run-scheduled-effects> buildbot # [   12.372460] dhcpcd[1114]: DUID 00:01:00:01:31:d3:78:15:52:54:00:12:34:56973vm-test-run-scheduled-effects> buildbot # [   12.374829] dhcpcd[1114]: eth0: IAID 00:12:34:56974vm-test-run-scheduled-effects> buildbot # [   12.377502] dhcpcd[1114]: eth0: adding address fe80::5054:ff:fe12:3456975vm-test-run-scheduled-effects> buildbot # [   12.385491] postgresql-pre-start[1135]: The files belonging to this database system will be owned by user "postgres".976vm-test-run-scheduled-effects> buildbot # [   12.388517] postgresql-pre-start[1135]: This user must also own the server process.977vm-test-run-scheduled-effects> buildbot # [   12.393832] nginx-pre-start[1133]: nginx: the configuration file /nix/store/993plri0ywsxjc40qj021rk6zmjw9nab-nginx.conf syntax is ok978vm-test-run-scheduled-effects> buildbot # [   12.396861] nginx-pre-start[1133]: nginx: configuration file /nix/store/993plri0ywsxjc40qj021rk6zmjw9nab-nginx.conf test is successful979vm-test-run-scheduled-effects> buildbot # [   12.409255] systemd[1]: Started Nginx Web Server.980vm-test-run-scheduled-effects> buildbot # [   12.415675] postgresql-pre-start[1135]: The database cluster will be initialized with locale "en_US.UTF-8".981vm-test-run-scheduled-effects> buildbot # [   12.417973] postgresql-pre-start[1135]: The default database encoding has accordingly been set to "UTF8".982vm-test-run-scheduled-effects> buildbot # [   12.420261] postgresql-pre-start[1135]: The default text search configuration will be set to "english".983vm-test-run-scheduled-effects> buildbot # [   12.422448] postgresql-pre-start[1135]: Data page checksums are disabled.984vm-test-run-scheduled-effects> buildbot # [   12.424871] postgresql-pre-start[1135]: fixing permissions on existing directory /var/lib/postgresql/17 ... ok985vm-test-run-scheduled-effects> buildbot # [   12.427544] postgresql-pre-start[1135]: creating subdirectories ... ok986vm-test-run-scheduled-effects> buildbot # [   12.430796] postgresql-pre-start[1135]: selecting dynamic shared memory implementation ... posix987vm-test-run-scheduled-effects> buildbot # [   12.447874] setup-git-repo-start[1154]: hint: Using 'master' as the name for the initial branch. This default branch name988vm-test-run-scheduled-effects> buildbot # [   12.450419] setup-git-repo-start[1154]: hint: will change to "main" in Git 3.0. To configure the initial branch name989vm-test-run-scheduled-effects> buildbot # [   12.452886] setup-git-repo-start[1154]: hint: to use in all of your new repositories, which will suppress this warning,990vm-test-run-scheduled-effects> buildbot # [   12.456772] setup-git-repo-start[1154]: hint: call:991vm-test-run-scheduled-effects> buildbot # [   12.459540] setup-git-repo-start[1154]: hint:992vm-test-run-scheduled-effects> buildbot # [   12.460853] setup-git-repo-start[1154]: hint: 	git config --global init.defaultBranch <name>993vm-test-run-scheduled-effects> buildbot # [   12.464177] setup-git-repo-start[1154]: hint:994vm-test-run-scheduled-effects> buildbot # [   12.465622] setup-git-repo-start[1154]: hint: Names commonly chosen instead of 'master' are 'main', 'trunk' and995vm-test-run-scheduled-effects> buildbot # [   12.468299] setup-git-repo-start[1154]: hint: 'development'. The just-created branch can be renamed via this command:996vm-test-run-scheduled-effects> buildbot # [   12.471201] setup-git-repo-start[1154]: hint:997vm-test-run-scheduled-effects> buildbot # [   12.472447] setup-git-repo-start[1154]: hint: 	git branch -m <name>998vm-test-run-scheduled-effects> buildbot # [   12.475246] setup-git-repo-start[1154]: hint:999vm-test-run-scheduled-effects> buildbot # [   12.476706] setup-git-repo-start[1154]: hint: Disable this message with "git config set advice.defaultBranchName false"1000vm-test-run-scheduled-effects> buildbot # [   12.479435] setup-git-repo-start[1154]: Initialized empty Git repository in /tmp/test-flake/.git/1001vm-test-run-scheduled-effects> buildbot # [   12.570878] setup-git-repo-start[1165]: [master (root-commit) 0117f9f] Initial commit with scheduled effects1002vm-test-run-scheduled-effects> buildbot # [   12.573831] setup-git-repo-start[1165]:  3 files changed, 131 insertions(+)1003vm-test-run-scheduled-effects> buildbot # [   12.578175] setup-git-repo-start[1165]:  create mode 100644 effects-lib.nix1004vm-test-run-scheduled-effects> buildbot # [   12.579895] setup-git-repo-start[1165]:  create mode 100644 flake.lock1005vm-test-run-scheduled-effects> buildbot # [   12.581496] setup-git-repo-start[1165]:  create mode 100644 flake.nix1006vm-test-run-scheduled-effects> buildbot # [   12.609192] postgresql-pre-start[1135]: selecting default "max_connections" ... 1001007vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit sshd.service, in 13.93 seconds)1008vm-test-run-scheduled-effects> buildbot: waiting for unit setup-git-repo.service1009vm-test-run-scheduled-effects> buildbot # [   12.721388] setup-git-repo-start[1172]: To /srv/repos/test-flake.git1010vm-test-run-scheduled-effects> buildbot # [   12.724173] setup-git-repo-start[1172]:  * [new branch]      master -> master1011vm-test-run-scheduled-effects> buildbot # [   12.726995] setup-git-repo-start[1172]: branch 'master' set up to track 'origin/master'.1012vm-test-run-scheduled-effects> buildbot # [   12.730058] postgresql-pre-start[1135]: selecting default "shared_buffers" ... 128MB1013vm-test-run-scheduled-effects> buildbot # [   12.735389] systemd[1]: Finished Setup git test repository with scheduled effects.1014vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit setup-git-repo.service, in 0.12 seconds)1015vm-test-run-scheduled-effects> buildbot: waiting for unit multi-user.target1016vm-test-run-scheduled-effects> buildbot # [   14.274406] dhcpcd[1114]: eth0: soliciting a DHCP lease1017vm-test-run-scheduled-effects> buildbot # [   14.545520] NET: Registered PF_PACKET protocol family1018vm-test-run-scheduled-effects> buildbot # [   14.308662] dhcpcd[1114]: eth0: offered 10.0.2.15 from 10.0.2.21019vm-test-run-scheduled-effects> buildbot # [   14.312233] dhcpcd[1114]: eth0: probing address 10.0.2.15/241020vm-test-run-scheduled-effects> buildbot # [   15.098416] dhcpcd[1114]: eth0: soliciting an IPv6 router1021vm-test-run-scheduled-effects> buildbot # [   15.100922] dhcpcd[1114]: eth0: Router Advertisement from fe80::21022vm-test-run-scheduled-effects> buildbot # [   15.102579] dhcpcd[1114]: eth0: adding address fec0::5054:ff:fe12:3456/641023vm-test-run-scheduled-effects> buildbot # [   15.104420] dhcpcd[1114]: eth0: adding route to fec0::/641024vm-test-run-scheduled-effects> buildbot # [   15.106669] dhcpcd[1114]: eth0: adding default route via fe80::21025vm-test-run-scheduled-effects> buildbot # [   16.294169] postgresql-pre-start[1135]: selecting default time zone ... UTC1026vm-test-run-scheduled-effects> buildbot # [   16.300483] postgresql-pre-start[1135]: creating configuration files ... ok1027vm-test-run-scheduled-effects> buildbot # [   16.570222] postgresql-pre-start[1135]: running bootstrap script ... ok1028vm-test-run-scheduled-effects> buildbot # [   17.269190] postgresql-pre-start[1135]: performing post-bootstrap initialization ... ok1029vm-test-run-scheduled-effects> buildbot # [   17.502419] postgresql-pre-start[1135]: syncing data to disk ... ok1030vm-test-run-scheduled-effects> buildbot # [   17.505132] postgresql-pre-start[1135]: initdb: warning: enabling "trust" authentication for local connections1031vm-test-run-scheduled-effects> buildbot # [   17.507451] postgresql-pre-start[1135]: 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.1032vm-test-run-scheduled-effects> buildbot # [   17.511130] postgresql-pre-start[1135]: Success. You can now start the database server using:1033vm-test-run-scheduled-effects> buildbot # [   17.513183] postgresql-pre-start[1135]:     pg_ctl -D /var/lib/postgresql/17 -l logfile start1034vm-test-run-scheduled-effects> buildbot # [   17.659544] postgres[1251]: [1251] LOG:  starting PostgreSQL 17.10 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit1035vm-test-run-scheduled-effects> buildbot # [   17.675236] postgres[1251]: [1251] LOG:  listening on IPv6 address "::1", port 54321036vm-test-run-scheduled-effects> buildbot # [   17.677330] postgres[1251]: [1251] LOG:  listening on IPv4 address "127.0.0.1", port 54321037vm-test-run-scheduled-effects> buildbot # [   17.680425] postgres[1251]: [1251] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"1038vm-test-run-scheduled-effects> buildbot # [   17.695370] postgres[1257]: [1257] LOG:  database system was shut down at 2026-06-28 06:13:45 GMT1039vm-test-run-scheduled-effects> buildbot # [   17.704848] postgres[1251]: [1251] LOG:  database system is ready to accept connections1040vm-test-run-scheduled-effects> buildbot # [   17.712988] systemd[1]: Started PostgreSQL Server.1041vm-test-run-scheduled-effects> buildbot # [   17.718930] systemd[1]: Starting PostgreSQL Setup Scripts...1042vm-test-run-scheduled-effects> buildbot # [   17.954788] postgresql-setup-start[1268]: CREATE DATABASE1043vm-test-run-scheduled-effects> buildbot # [   18.019294] postgresql-setup-start[1273]: CREATE ROLE1044vm-test-run-scheduled-effects> buildbot # [   18.050955] postgresql-setup-start[1275]: ALTER DATABASE1045vm-test-run-scheduled-effects> buildbot # [   18.058648] systemd[1]: Finished PostgreSQL Setup Scripts.1046vm-test-run-scheduled-effects> buildbot # [   18.060920] systemd[1]: Reached target PostgreSQL.1047vm-test-run-scheduled-effects> buildbot # [   18.066659] systemd[1]: Starting Buildbot Continuous Integration Server....1048vm-test-run-scheduled-effects> buildbot # [   18.141144] buildbot-master-pre-start[1280]: mkdir: created directory '/var/lib/buildbot/master'1049vm-test-run-scheduled-effects> buildbot # [   18.430309] dhcpcd[1114]: eth0: leased 10.0.2.15 for 86400 seconds1050vm-test-run-scheduled-effects> buildbot # [   18.432161] dhcpcd[1114]: eth0: adding route to 10.0.2.0/241051vm-test-run-scheduled-effects> buildbot # [   18.433810] dhcpcd[1114]: eth0: adding default route via 10.0.2.21052vm-test-run-scheduled-effects> buildbot # [   18.594460] systemd[1]: Started DHCP Client.1053vm-test-run-scheduled-effects> buildbot # [   27.375072] buildbot-master-pre-start[1282]: updating existing installation1054vm-test-run-scheduled-effects> buildbot # [   27.376946] buildbot-master-pre-start[1282]: not touching existing buildbot.tac1055vm-test-run-scheduled-effects> buildbot # [   27.380112] buildbot-master-pre-start[1282]: creating buildbot.tac.new instead1056vm-test-run-scheduled-effects> buildbot # [   27.381899] buildbot-master-pre-start[1282]: creating /var/lib/buildbot/master/master.cfg.sample1057vm-test-run-scheduled-effects> buildbot # [   27.384002] buildbot-master-pre-start[1282]: creating database (postgresql://@/buildbot)1058vm-test-run-scheduled-effects> buildbot # [   27.385988] buildbot-master-pre-start[1282]: buildmaster configured in /var/lib/buildbot/master1059vm-test-run-scheduled-effects> buildbot # [   27.643214] systemd[1]: Started Buildbot Continuous Integration Server..1060vm-test-run-scheduled-effects> buildbot # [   27.650197] systemd[1]: Started Buildbot Worker..1061vm-test-run-scheduled-effects> buildbot # [   27.652466] systemd[1]: Reached target Multi-User System.1062vm-test-run-scheduled-effects> buildbot # [   27.654529] systemd[1]: Startup finished in 939ms (kernel) + 4.497s (initrd) + 22.216s (userspace) = 27.653s.1063vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit multi-user.target, in 15.87 seconds)1064vm-test-run-scheduled-effects> subtest: Master and worker services start1065vm-test-run-scheduled-effects> buildbot: waiting for unit buildbot-master.service1066vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit buildbot-master.service, in 0.11 seconds)1067vm-test-run-scheduled-effects> buildbot: waiting for unit buildbot-worker.service1068vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit buildbot-worker.service, in 0.10 seconds)1069vm-test-run-scheduled-effects> buildbot: waiting for TCP port 8010 on localhost1070vm-test-run-scheduled-effects> buildbot # [   29.803484] twistd[1419]: Starting worker local-worker-0001071vm-test-run-scheduled-effects> buildbot # [   29.805310] twistd[1419]: 2026-06-28T06:13:57+0000 [-] Loading /nix/store/zxbh9svi0g0i80pg7z3gd6hmk17ck3yf-buildbot_nix/buildbot_nix/worker.py...1072vm-test-run-scheduled-effects> buildbot # [   29.809451] twistd[1419]: 2026-06-28T06:13:58+0000 [-] Loaded.1073vm-test-run-scheduled-effects> buildbot # [   29.810980] twistd[1419]: 2026-06-28T06:13:58+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] twistd 25.5.0 (/nix/store/60m4rxhg2fldqaak400c0lry96ijrzqn-python3-3.13.13/bin/python3.13 3.13.13) starting up.1074vm-test-run-scheduled-effects> buildbot # [   29.815567] twistd[1419]: 2026-06-28T06:13:58+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] reactor class: twisted.internet.epollreactor.EPollReactor.1075vm-test-run-scheduled-effects> buildbot # [   29.818863] twistd[1419]: 2026-06-28T06:13:58+0000 [-] Starting Worker -- version: 2026.05.221076vm-test-run-scheduled-effects> buildbot # [   29.821314] twistd[1419]: 2026-06-28T06:13:58+0000 [-] recording hostname in twistd.hostname1077vm-test-run-scheduled-effects> buildbot # [   29.823488] twistd[1419]: 2026-06-28T06:13:58+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x739f6c9c8590>1078vm-test-run-scheduled-effects> buildbot # [   29.836780] twistd[1419]: 2026-06-28T06:13:58+0000 [twisted.application._client_service.ClientService#info] Scheduling retry 1 to connect <twisted.internet.endpoints.TCP4ClientEndpoint object at 0x739f6c9c8ad0> in 2.4469614356374745 seconds.1079vm-test-run-scheduled-effects> buildbot # [   29.841358] twistd[1419]: 2026-06-28T06:13:58+0000 [buildbot_worker.pb.BotFactory#info] Stopping factory <buildbot_worker.pb.BotFactory object at 0x739f6c9c8590>1080vm-test-run-scheduled-effects> buildbot # [   32.287482] twistd[1419]: 2026-06-28T06:14:00+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x739f6c9c8590>1081vm-test-run-scheduled-effects> buildbot # [   32.293525] twistd[1419]: 2026-06-28T06:14:00+0000 [twisted.application._client_service.ClientService#info] Scheduling retry 2 to connect <twisted.internet.endpoints.TCP4ClientEndpoint object at 0x739f6c9c8ad0> in 2.495584412699093 seconds.1082vm-test-run-scheduled-effects> buildbot # [   32.298382] twistd[1419]: 2026-06-28T06:14:00+0000 [buildbot_worker.pb.BotFactory#info] Stopping factory <buildbot_worker.pb.BotFactory object at 0x739f6c9c8590>1083vm-test-run-scheduled-effects> buildbot # [   32.806915] twistd[1418]: 2026-06-28T06:13:57+0000 [-] Loading /var/lib/buildbot/master/buildbot.tac...1084vm-test-run-scheduled-effects> buildbot # [   32.810046] twistd[1418]: 2026-06-28T06:14:01+0000 [-] Loaded.1085vm-test-run-scheduled-effects> buildbot # [   32.811653] twistd[1418]: 2026-06-28T06:14:01+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] twistd 25.5.0 (/nix/store/60m4rxhg2fldqaak400c0lry96ijrzqn-python3-3.13.13/bin/python3.13 3.13.13) starting up.1086vm-test-run-scheduled-effects> buildbot # [   32.815783] twistd[1418]: 2026-06-28T06:14:01+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] reactor class: twisted.internet.epollreactor.EPollReactor.1087vm-test-run-scheduled-effects> buildbot # [   32.818983] twistd[1418]: 2026-06-28T06:14:01+0000 [-] Starting BuildMaster -- buildbot.version: 4.3.01088vm-test-run-scheduled-effects> buildbot # [   32.834883] twistd[1418]: 2026-06-28T06:14:01+0000 [-] Loading configuration from '/nix/store/lrw01m59h52qsb3jnqd1wm6qfaj4z4sv-master.cfg'1089vm-test-run-scheduled-effects> buildbot # [   34.161509] twistd[1418]: 2026-06-28T06:14:02+0000 [-] Setting up database with URL 'postgresql://@/buildbot'1090vm-test-run-scheduled-effects> buildbot # [   34.300764] twistd[1418]: 2026-06-28T06:14:02+0000 [-] adding 9 new builders, removing 01091vm-test-run-scheduled-effects> buildbot # [   34.437211] twistd[1418]: 2026-06-28T06:14:03+0000 [-] adding 3 new services, removing 01092vm-test-run-scheduled-effects> buildbot # [   34.559898] twistd[1418]: 2026-06-28T06:14:03+0000 [-] adding 1 new change_sources, removing 01093vm-test-run-scheduled-effects> buildbot # [   34.567825] twistd[1418]: 2026-06-28T06:14:03+0000 [-] gitpoller: using workdir '/var/lib/buildbot/master/gitpoller-work'1094vm-test-run-scheduled-effects> buildbot # [   34.576707] twistd[1418]: 2026-06-28T06:14:03+0000 [-] adding 14 new schedulers, removing 01095vm-test-run-scheduled-effects> buildbot # [   34.792443] twistd[1419]: 2026-06-28T06:14:03+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x739f6c9c8590>1096vm-test-run-scheduled-effects> buildbot # [   34.798330] twistd[1419]: 2026-06-28T06:14:03+0000 [twisted.application._client_service.ClientService#info] Scheduling retry 3 to connect <twisted.internet.endpoints.TCP4ClientEndpoint object at 0x739f6c9c8ad0> in 3.6074336760485957 seconds.1097vm-test-run-scheduled-effects> buildbot # [   34.803304] twistd[1419]: 2026-06-28T06:14:03+0000 [buildbot_worker.pb.BotFactory#info] Stopping factory <buildbot_worker.pb.BotFactory object at 0x739f6c9c8590>1098vm-test-run-scheduled-effects> buildbot # [   34.825129] twistd[1418]: 2026-06-28T06:14:03+0000 [-] BuildbotSite starting on 80101099vm-test-run-scheduled-effects> buildbot # [   34.827086] twistd[1418]: 2026-06-28T06:14:03+0000 [buildbot.www.service.BuildbotSite#info] Starting factory <buildbot.www.service.BuildbotSite object at 0x74b9925f0980>1100vm-test-run-scheduled-effects> buildbot # [   34.830971] twistd[1418]: 2026-06-28T06:14:03+0000 [-] adding 5 new workers, removing 01101vm-test-run-scheduled-effects> buildbot # [   34.847452] twistd[1418]: 2026-06-28T06:14:03+0000 [-] PBServerFactory starting on 99891102vm-test-run-scheduled-effects> buildbot # [   34.849392] twistd[1418]: 2026-06-28T06:14:03+0000 [twisted.spread.pb.PBServerFactory#info] Starting factory <twisted.spread.pb.PBServerFactory object at 0x74b9925f1400>1103vm-test-run-scheduled-effects> buildbot # [   34.877452] twistd[1418]: 2026-06-28T06:14:03+0000 [-] Starting Worker -- version: 2026.05.221104vm-test-run-scheduled-effects> buildbot # [   34.879553] twistd[1418]: 2026-06-28T06:14:03+0000 [-] recording hostname in twistd.hostname1105vm-test-run-scheduled-effects> buildbot # [   34.881542] twistd[1418]: 2026-06-28T06:14:03+0000 [-] message from master: attached1106vm-test-run-scheduled-effects> buildbot # [   34.885060] twistd[1418]: 2026-06-28T06:14:03+0000 [-] Got workerinfo from '__Janitor'1107vm-test-run-scheduled-effects> buildbot # [   34.894948] twistd[1418]: 2026-06-28T06:14:03+0000 [-] bot attached1108vm-test-run-scheduled-effects> buildbot # [   34.896557] twistd[1418]: 2026-06-28T06:14:03+0000 [-] Worker __Janitor attached to __Janitor1109vm-test-run-scheduled-effects> buildbot # [   34.898556] twistd[1418]: 2026-06-28T06:14:03+0000 [-] message from master: attached1110vm-test-run-scheduled-effects> buildbot # [   34.952894] twistd[1418]: 2026-06-28T06:14:03+0000 [-] BuildMaster is running1111vm-test-run-scheduled-effects> buildbot # [   34.991407] sshd-session[1488]: Accepted publickey for root from ::1 port 49298 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81112vm-test-run-scheduled-effects> buildbot # [   35.009570] sshd-session[1488]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1113vm-test-run-scheduled-effects> buildbot # [   35.057669] systemd[1]: Created slice Slice /user/0.1114vm-test-run-scheduled-effects> buildbot # [   35.063230] systemd[1]: Starting User Runtime Directory /run/user/0...1115vm-test-run-scheduled-effects> buildbot # [   35.077860] systemd-logind[970]: New session '1' of user 'root' with class 'user' and type 'tty'.1116vm-test-run-scheduled-effects> buildbot # [   35.120112] systemd[1]: Finished User Runtime Directory /run/user/0.1117vm-test-run-scheduled-effects> buildbot # [   35.127221] systemd[1]: Starting User Manager for UID 0...1118vm-test-run-scheduled-effects> buildbot # [   35.180147] (systemd)[1494]: pam_unix(systemd-user:session): session opened for user root(uid=0) by (uid=0)1119vm-test-run-scheduled-effects> buildbot # [   35.189392] systemd-logind[970]: New session '2' of user 'root' with class 'manager-early' and type 'unspecified'.1120vm-test-run-scheduled-effects> buildbot # Connection to localhost (127.0.0.1) 8010 port [tcp/*] succeeded!1121vm-test-run-scheduled-effects> buildbot: (finished: waiting for TCP port 8010 on localhost, in 6.49 seconds)1122vm-test-run-scheduled-effects> buildbot: waiting for success: curl --fail --head http://localhost:80101123vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1124vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1125vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0  0      0   0      0   0      0      0      0                              0  0      0   0      0   0      0      0      0                              0  0      0   0      0   0      0      0      0                              01126vm-test-run-scheduled-effects> buildbot: (finished: waiting for success: curl --fail --head http://localhost:8010, in 0.21 seconds)1127vm-test-run-scheduled-effects> (finished: subtest: Master and worker services start, in 6.92 seconds)1128vm-test-run-scheduled-effects> subtest: Project is registered1129vm-test-run-scheduled-effects> buildbot: waiting for success: curl http://localhost:8010/api/v2/projects1130vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1131vm-test-run-scheduled-effects> buildbot #           [   35.664602] systemd[1494]: Queued start job for default target Main User Target.1132vm-test-run-scheduled-effects> buildbot #                  [   35.670882] systemd[1494]: Created slice User Application Slice.1133vm-test-run-scheduled-effects> buildbot #       Dl[   35.675151] systemd[1494]: Started Daily Cleanup of User's Temporary Directories.1134vm-test-run-scheduled-effects> buildbot # [   35.677087] systemd[1494]: Reached target Paths.1135vm-test-run-scheduled-effects> buildbot # oad  U[   35.679632] systemd[1494]: Reached target Timers.1136vm-test-run-scheduled-effects> buildbot # pload  Total[   35.684175] systemd[1494]: Starting D-Bus User Message Bus Socket...1137vm-test-run-scheduled-effects> buildbot #    Spent   Left   Speed1138vm-test-run-scheduled-effects> buildbot # [   35.690613] systemd[1494]: Starting Create User Files and Directories...1139vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    266 100    266   0      0   3748      0                              0100    266 100    266   0      0   2992      0                              0100    266 100    266   0      0   2510      0                              01140vm-test-run-scheduled-effects> buildbot: (finished: waiting for success: curl http://localhost:8010/api/v2/projects, in 0.20 seconds)1141vm-test-run-scheduled-effects> (finished: subtest: Project is registered, in 0.20 seconds)1142vm-test-run-scheduled-effects> subtest: CLI list-schedules works1143vm-test-run-scheduled-effects> buildbot: must succeed: 1144vm-test-run-scheduled-effects>         cd /tmp/test-flake1145vm-test-run-scheduled-effects>         buildbot-effects list-schedules1146vm-test-run-scheduled-effects>     1147vm-test-run-scheduled-effects> buildbot # [   35.786122] systemd[1494]: Finished Create User Files and Directories.1148vm-test-run-scheduled-effects> buildbot # [   35.835116] systemd[1494]: Listening on D-Bus User Message Bus Socket.1149vm-test-run-scheduled-effects> buildbot # [   35.837518] systemd[1494]: Reached target Sockets.1150vm-test-run-scheduled-effects> buildbot # [   35.843285] systemd[1494]: Reached target Basic System.1151vm-test-run-scheduled-effects> buildbot # [   35.845771] systemd[1494]: Run user-specific NixOS activation skipped, unmet condition check ConditionUser=!@system1152vm-test-run-scheduled-effects> buildbot # [   35.848458] systemd[1494]: Reached target Main User Target.1153vm-test-run-scheduled-effects> buildbot # [   35.852153] systemd[1494]: Startup finished in 617ms.1154vm-test-run-scheduled-effects> buildbot # [   35.854274] systemd[1]: Started User Manager for UID 0.1155vm-test-run-scheduled-effects> buildbot # [   35.855784] systemd[1]: Started Session 1 of User root.1156vm-test-run-scheduled-effects> buildbot # [   35.906347] sshd-session[1522]: Received disconnect from ::1 port 49298:11: disconnected by user1157vm-test-run-scheduled-effects> buildbot # [   35.908630] sshd-session[1522]: Disconnected from user root ::1 port 492981158vm-test-run-scheduled-effects> buildbot # [   35.911940] sshd-session[1488]: pam_unix(sshd:session): session closed for user root1159vm-test-run-scheduled-effects> buildbot # [   35.925511] systemd[1]: session-1.scope: Deactivated successfully.1160vm-test-run-scheduled-effects> buildbot # [   35.930427] systemd-logind[970]: Session 1 logged out. Waiting for processes to exit.1161vm-test-run-scheduled-effects> buildbot # [   35.934442] systemd-logind[970]: Removed session 1.1162vm-test-run-scheduled-effects> buildbot # [   36.116500] sshd-session[1527]: Accepted publickey for root from ::1 port 49314 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81163vm-test-run-scheduled-effects> buildbot # [   36.137884] sshd-session[1527]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1164vm-test-run-scheduled-effects> buildbot # [   36.150731] systemd-logind[970]: New session '3' of user 'root' with class 'user' and type 'tty'.1165vm-test-run-scheduled-effects> buildbot # [   36.158356] systemd[1]: Started Session 3 of User root.1166vm-test-run-scheduled-effects> buildbot # [   36.225621] sshd-session[1532]: Received disconnect from ::1 port 49314:11: disconnected by user1167vm-test-run-scheduled-effects> buildbot # [   36.229373] sshd-session[1532]: Disconnected from user root ::1 port 493141168vm-test-run-scheduled-effects> buildbot # [   36.233673] sshd-session[1527]: pam_unix(sshd:session): session closed for user root1169vm-test-run-scheduled-effects> buildbot # [   36.239190] systemd[1]: session-3.scope: Deactivated successfully.1170vm-test-run-scheduled-effects> buildbot # [   36.246269] systemd-logind[970]: Session 3 logged out. Waiting for processes to exit.1171vm-test-run-scheduled-effects> buildbot # [   36.250352] systemd-logind[970]: Removed session 3.1172vm-test-run-scheduled-effects> buildbot # [   36.280821] twistd[1418]: 2026-06-28T06:14:04+0000 [-] gitpoller: processing changes from "ssh://root@localhost/srv/repos/test-flake.git"1173vm-test-run-scheduled-effects> buildbot: (finished: must succeed: 1174vm-test-run-scheduled-effects>         cd /tmp/test-flake1175vm-test-run-scheduled-effects>         buildbot-effects list-schedules1176vm-test-run-scheduled-effects>     , in 0.72 seconds)1177vm-test-run-scheduled-effects> (finished: subtest: CLI list-schedules works, in 0.72 seconds)1178vm-test-run-scheduled-effects> subtest: Push a new commit to trigger build1179vm-test-run-scheduled-effects> buildbot: must succeed: 1180vm-test-run-scheduled-effects>         cd /tmp/test-flake1181vm-test-run-scheduled-effects>         echo "# trigger rebuild" >> flake.nix1182vm-test-run-scheduled-effects>         git add flake.nix1183vm-test-run-scheduled-effects>         git commit -m "Trigger build"1184vm-test-run-scheduled-effects>         git push origin master1185vm-test-run-scheduled-effects>     1186vm-test-run-scheduled-effects> buildbot # Enumerating objects: 5, done.1187vm-test-run-scheduled-effects> buildbot # Counting objects:  20% (1/5)Counting objects:  40% (2/5)Counting objects:  60% (3/5)Counting objects:  80% (4/5)Counting objects: 100% (5/5)Counting objects: 100% (5/5), done.1188vm-test-run-scheduled-effects> buildbot # Compressing objects:  33% (1/3)Compressing objects:  66% (2/3)Compressing objects: 100% (3/3)Compressing objects: 100% (3/3), done.1189vm-test-run-scheduled-effects> buildbot # Writing objects:  33% (1/3)Writing objects:  66% (2/3)Writing objects: 100% (3/3)Writing objects: 100% (3/3), 296 bytes | 98.00 KiB/s, done.1190vm-test-run-scheduled-effects> buildbot # Total 3 (delta 2), reused 0 (delta 0), pack-reused 0 (from 0)1191vm-test-run-scheduled-effects> buildbot # To /srv/repos/test-flake.git1192vm-test-run-scheduled-effects> buildbot #    0117f9f..1db2e98  master -> master1193vm-test-run-scheduled-effects> buildbot: (finished: must succeed: 1194vm-test-run-scheduled-effects>         cd /tmp/test-flake1195vm-test-run-scheduled-effects>         echo "# trigger rebuild" >> flake.nix1196vm-test-run-scheduled-effects>         git add flake.nix1197vm-test-run-scheduled-effects>         git commit -m "Trigger build"1198vm-test-run-scheduled-effects>         git push origin master1199vm-test-run-scheduled-effects>     , in 0.16 seconds)1200vm-test-run-scheduled-effects> (finished: subtest: Push a new commit to trigger build, in 0.16 seconds)1201vm-test-run-scheduled-effects> subtest: Wait for nix-eval build to complete1202vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1203vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1204vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1205vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1233      0                              0100     51 100     51   0      0    978      0                              0100     51 100     51   0      0    817      0                              01206vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.14 seconds)1207vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1208vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1209vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1210vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0    890      0                              0100     51 100     51   0      0    713      0                              0100     51 100     51   0      0    577      0                              01211vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.21 seconds)1212vm-test-run-scheduled-effects> buildbot # [   38.417790] twistd[1419]: 2026-06-28T06:14:07+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x739f6c9c8590>1213vm-test-run-scheduled-effects> buildbot # [   38.440944] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] worker 'local-worker-000' attaching from IPv4Address(type='TCP', host='127.0.0.1', port=58854)1214vm-test-run-scheduled-effects> buildbot # [   38.451117] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1215vm-test-run-scheduled-effects> buildbot # [   38.468181] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Got workerinfo from 'local-worker-000'1216vm-test-run-scheduled-effects> buildbot # [   38.485482] twistd[1418]: 2026-06-28T06:14:07+0000 [-] bot attached1217vm-test-run-scheduled-effects> buildbot # [   38.492592] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-cached-failure1218vm-test-run-scheduled-effects> buildbot # [   38.495705] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-build1219vm-test-run-scheduled-effects> buildbot # [   38.498610] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-dependency-failed1220vm-test-run-scheduled-effects> buildbot # [   38.502968] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/run-effect1221vm-test-run-scheduled-effects> buildbot # [   38.505823] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/run-scheduled-effect1222vm-test-run-scheduled-effects> buildbot # [   38.508683] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-register-gcroot1223vm-test-run-scheduled-effects> buildbot # [   38.511573] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-eval1224vm-test-run-scheduled-effects> buildbot # [   38.515125] twistd[1418]: 2026-06-28T06:14:07+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-failed-eval1225vm-test-run-scheduled-effects> buildbot # [   38.518042] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1226vm-test-run-scheduled-effects> buildbot # [   38.520214] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1227vm-test-run-scheduled-effects> buildbot # [   38.524339] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1228vm-test-run-scheduled-effects> buildbot # [   38.526522] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1229vm-test-run-scheduled-effects> buildbot # [   38.528632] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1230vm-test-run-scheduled-effects> buildbot # [   38.530777] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1231vm-test-run-scheduled-effects> buildbot # [   38.533899] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1232vm-test-run-scheduled-effects> buildbot # [   38.535970] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] message from master: attached1233vm-test-run-scheduled-effects> buildbot # [   38.551753] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] Connected to buildmaster; worker is ready1234vm-test-run-scheduled-effects> buildbot # [   38.554210] twistd[1419]: 2026-06-28T06:14:07+0000 [Broker,client] sending application-level keepalives every 600 seconds1235vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1236vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1237vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1238vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1295      0                              0100     51 100     51   0      0   1026      0                              0100     51 100     51   0      0    850      0                              01239vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1240vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1241vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1242vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1243vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1302      0                              0100     51 100     51   0      0   1022      0                              0100     51 100     51   0      0    849      0                              01244vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1245vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1246vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1247vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1248vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1275      0                              0100     51 100     51   0      0    983      0                              0100     51 100     51   0      0    819      0                              01249vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.17 seconds)1250vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1251vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1252vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1253vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1265      0                              0100     51 100     51   0      0    993      0                              0100     51 100     51   0      0    818      0                              01254vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1255vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1256vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1257vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1258vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1194      0                              0100     51 100     51   0      0    962      0                              0100     51 100     51   0      0    808      0                              01259vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.17 seconds)1260vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1261vm-test-run-scheduled-effects> buildbot # [   44.861437] sshd-session[1599]: Accepted publickey for root from ::1 port 32838 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81262vm-test-run-scheduled-effects> buildbot # [   44.879806] sshd-session[1599]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1263vm-test-run-scheduled-effects> buildbot # [   44.893327] systemd-logind[970]: New session '4' of user 'root' with class 'user' and type 'tty'.1264vm-test-run-scheduled-effects> buildbot # [   44.897453] systemd[1]: Started Session 4 of User root.1265vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1266vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1267vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100    [   44.965956] sshd-session[1605]: Received disconnect from ::1 port 32838:11: disconnected by user1268vm-test-run-scheduled-effects> buildbot #  51   0 [   44.972114] sshd-session[1605]: Disconnected from user root ::1 port 328381269vm-test-run-scheduled-effects> buildbot #     [   44.975612] sshd-session[1599]: pam_unix(sshd:session): session closed for user root1270vm-test-run-scheduled-effects> buildbot #  0   1030[   44.980632] systemd[1]: session-4.scope: Deactivated successfully.1271vm-test-run-scheduled-effects> buildbot #       0             [   44.991322] systemd-logind[970]: Session 4 logged out. Waiting for processes to exit.1272vm-test-run-scheduled-effects> buildbot #            [   44.996114] systemd-logind[970]: Removed session 4.1273vm-test-run-scheduled-effects> buildbot #       0100     51 100     51   0      0    564      0                              0100     51 100     51   0      0    481      0                              01274vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.22 seconds)1275vm-test-run-scheduled-effects> buildbot # [   45.226497] sshd-session[1610]: Accepted publickey for root from ::1 port 32846 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81276vm-test-run-scheduled-effects> buildbot # [   45.247841] sshd-session[1610]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1277vm-test-run-scheduled-effects> buildbot # [   45.259109] systemd-logind[970]: New session '5' of user 'root' with class 'user' and type 'tty'.1278vm-test-run-scheduled-effects> buildbot # [   45.264439] systemd[1]: Started Session 5 of User root.1279vm-test-run-scheduled-effects> buildbot # [   45.326104] sshd-session[1613]: Received disconnect from ::1 port 32846:11: disconnected by user1280vm-test-run-scheduled-effects> buildbot # [   45.328541] sshd-session[1613]: Disconnected from user root ::1 port 328461281vm-test-run-scheduled-effects> buildbot # [   45.331879] sshd-session[1610]: pam_unix(sshd:session): session closed for user root1282vm-test-run-scheduled-effects> buildbot # [   45.339545] systemd[1]: session-5.scope: Deactivated successfully.1283vm-test-run-scheduled-effects> buildbot # [   45.343404] systemd-logind[970]: Session 5 logged out. Waiting for processes to exit.1284vm-test-run-scheduled-effects> buildbot # [   45.347686] systemd-logind[970]: Removed session 5.1285vm-test-run-scheduled-effects> buildbot # [   45.372316] twistd[1418]: 2026-06-28T06:14:14+0000 [-] gitpoller: processing changes from "ssh://root@localhost/srv/repos/test-flake.git"1286vm-test-run-scheduled-effects> buildbot # [   45.408545] twistd[1418]: 2026-06-28T06:14:14+0000 [-] gitpoller: processing 1 changes: ['1db2e9832193edc65e0de43ca6fed9b63bfb2d5b'] from "ssh://root@localhost/srv/repos/test-flake.git" branch "refs/heads/master"1287vm-test-run-scheduled-effects> buildbot # [   45.495212] twistd[1418]: 2026-06-28T06:14:14+0000 [-] added change with revision 1db2e9832193edc65e0de43ca6fed9b63bfb2d5b to database1288vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1289vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1290vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1291vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1262      0                              0100     51 100     51   0      0   1010      0                              0100     51 100     51   0      0    843      0                              01292vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1293vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1294vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1295vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1296vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1274      0                              0100     51 100     51   0      0   1016      0                              0100     51 100     51   0      0    846      0                              01297vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1298vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1299vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1300vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1301vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1279      0                              0100     51 100     51   0      0   1014      0                              0100     51 100     51   0      0    846      0                              01302vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1303vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1304vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1305vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1306vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1253      0                              0100     51 100     51   0      0   1005      0                              0100     51 100     51   0      0    839      0                              01307vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1308vm-test-run-scheduled-effects> buildbot # [   50.547560] twistd[1418]: 2026-06-28T06:14:19+0000 [-] added buildset 1 to database1309vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1310vm-test-run-scheduled-effects> buildbot # [   50.715508] twistd[1418]: 2026-06-28T06:14:19+0000 [-] starting build <Build test-flake/nix-eval number:None results:success> using worker <WorkerForBuilder builder='test-flake/nix-eval' worker='local-worker-000' state=AVAILABLE>1311vm-test-run-scheduled-effects> buildbot # [   50.720574] twistd[1418]: 2026-06-28T06:14:19+0000 [-] <Build test-flake/nix-eval number:None results:success>.startBuild1312vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1313vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1314vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    401 100    401   0      0  [   50.822235] twistd[1418]: 2026-06-28T06:14:19+0000 [-] acquireLocks(worker <Worker 'local-worker-000'>, locks [])1315vm-test-run-scheduled-effects> buildbot #  7593      0                [   50.831135] twistd[1418]: 2026-06-28T06:14:19+0000 [-] starting build <Build test-flake/nix-eval number:1 results:success>.. pinging the worker <WorkerForBuilder builder='test-flake/nix-eval' worker='local-worker-000' state=BUILDING>1316vm-test-run-scheduled-effects> buildbot # [   50.835566] twistd[1418]: 2026-06-28T06:14:19+0000 [-] sending ping1317vm-test-run-scheduled-effects> buildbot #              [   50.840194] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] message from master: ping1318vm-test-run-scheduled-effects> buildbot # [   50.842726] twistd[1418]: 2026-06-28T06:14:19+0000 [Broker,0,127.0.0.1] ping finished: success1319vm-test-run-scheduled-effects> buildbot #  0100    401 100    401   0      0   4844      0                              0100    401 100    401   0      0   4069      0                              01320vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.21 seconds)1321vm-test-run-scheduled-effects> buildbot # [   50.892043] twistd[1418]: 2026-06-28T06:14:19+0000 [-] <RemoteShellCommand '['git', '--version']'>: RemoteCommand.run [0]1322vm-test-run-scheduled-effects> buildbot # [   50.894598] twistd[1418]: 2026-06-28T06:14:19+0000 [-] command '['git', '--version']' in dir 'build'1323vm-test-run-scheduled-effects> buildbot # [   50.897622] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 0): startCommand:shell1324vm-test-run-scheduled-effects> buildbot # [   50.901356] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '--version']): RunProcess._startCommand1325vm-test-run-scheduled-effects> buildbot # [   50.904195] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '--version']):  git --version1326vm-test-run-scheduled-effects> buildbot # [   50.908981] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '--version']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1327vm-test-run-scheduled-effects> buildbot # [   50.912704] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '--version']):   watching logfiles {}1328vm-test-run-scheduled-effects> buildbot # [   50.915282] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '--version']):   argv: [b'git', b'--version']1329vm-test-run-scheduled-effects> buildbot # [   50.917935] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '--version']):   using PTY: False1330vm-test-run-scheduled-effects> buildbot # [   50.936543] twistd[1419]: 2026-06-28T06:14:19+0000 [-] (command ['git', '--version']): command finished with signal None, exit code 0, elapsedTime: 0.0286611331vm-test-run-scheduled-effects> buildbot # [   50.940066] twistd[1419]: 2026-06-28T06:14:19+0000 [-] (command 0): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c9c9400>1332vm-test-run-scheduled-effects> buildbot # [   50.968212] twistd[1418]: 2026-06-28T06:14:19+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['git', '--version']'> rc=01333vm-test-run-scheduled-effects> buildbot # [   51.011340] twistd[1418]: 2026-06-28T06:14:19+0000 [-] <RemoteCommand 'stat' at 128340338590784>: RemoteCommand.run [1]1334vm-test-run-scheduled-effects> buildbot # [   51.017095] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 1): startCommand:stat1335vm-test-run-scheduled-effects> buildbot # [   51.019241] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 1): StatFile /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build/.buildbot-patched failed: [Errno 2] No such file or directory: '/var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build/.buildbot-patched'1336vm-test-run-scheduled-effects> buildbot # [   51.024844] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 1): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.fs.StatFile object at 0x739f6c9cacf0>1337vm-test-run-scheduled-effects> buildbot # [   51.028616] twistd[1418]: 2026-06-28T06:14:19+0000 [Broker,0,127.0.0.1] <RemoteCommand 'stat' at 128340338590784> rc=21338vm-test-run-scheduled-effects> buildbot # [   51.043516] twistd[1418]: 2026-06-28T06:14:19+0000 [-] <RemoteCommand 'mkdir' at 128340338129360>: RemoteCommand.run [2]1339vm-test-run-scheduled-effects> buildbot # [   51.074183] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 2): startCommand:mkdir1340vm-test-run-scheduled-effects> buildbot # [   51.076650] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 2): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.fs.MakeDirectory object at 0x739f6c9caba0>1341vm-test-run-scheduled-effects> buildbot # [   51.082338] twistd[1418]: 2026-06-28T06:14:19+0000 [Broker,0,127.0.0.1] <RemoteCommand 'mkdir' at 128340338129360> rc=01342vm-test-run-scheduled-effects> buildbot # [   51.091381] twistd[1418]: 2026-06-28T06:14:19+0000 [-] <RemoteCommand 'downloadFile' at 128340338130320>: RemoteCommand.run [3]1343vm-test-run-scheduled-effects> buildbot # [   51.123923] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 3): startCommand:downloadFile1344vm-test-run-scheduled-effects> buildbot # [   51.128842] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 3): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.transfer.WorkerFileDownloadCommand object at 0x739f6c9caf90>1345vm-test-run-scheduled-effects> buildbot # [   51.134159] twistd[1418]: 2026-06-28T06:14:19+0000 [Broker,0,127.0.0.1] <RemoteCommand 'downloadFile' at 128340338130320> rc=01346vm-test-run-scheduled-effects> buildbot # [   51.143844] twistd[1418]: 2026-06-28T06:14:19+0000 [-] <RemoteCommand 'listdir' at 128340338130640>: RemoteCommand.run [4]1347vm-test-run-scheduled-effects> buildbot # [   51.179109] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 4): startCommand:listdir1348vm-test-run-scheduled-effects> buildbot # [   51.181330] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 4): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.fs.ListDir object at 0x739f6c9cae40>1349vm-test-run-scheduled-effects> buildbot # [   51.186353] twistd[1418]: 2026-06-28T06:14:19+0000 [Broker,0,127.0.0.1] <RemoteCommand 'listdir' at 128340338130640> rc=01350vm-test-run-scheduled-effects> buildbot # [   51.195658] twistd[1418]: 2026-06-28T06:14:19+0000 [-] No git repo present, making full clone1351vm-test-run-scheduled-effects> buildbot # [   51.199213] twistd[1418]: 2026-06-28T06:14:19+0000 [-] <RemoteShellCommand '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']'>: RemoteCommand.run [5]1352vm-test-run-scheduled-effects> buildbot # [   51.205460] twistd[1418]: 2026-06-28T06:14:19+0000 [-] command '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']' in dir 'build'1353vm-test-run-scheduled-effects> buildbot # [   51.231164] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command 5): startCommand:shell1354vm-test-run-scheduled-effects> buildbot # [   51.234189] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']): RunProcess._startCommand1355vm-test-run-scheduled-effects> buildbot # [   51.240515] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']):  git -c 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"' clone --branch master ssh://root@localhost/srv/repos/test-flake.git . --progress1356vm-test-run-scheduled-effects> buildbot # [   51.266193] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1357vm-test-run-scheduled-effects> buildbot # [   51.273922] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']):   watching logfiles {}1358vm-test-run-scheduled-effects> buildbot # [   51.280220] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']):   argv: [b'git', b'-c', b'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', b'clone', b'--branch', b'master', b'ssh://root@localhost/srv/repos/test-flake.git', b'.', b'--progress']1359vm-test-run-scheduled-effects> buildbot # [   51.290703] twistd[1419]: 2026-06-28T06:14:19+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']):   using PTY: False1360vm-test-run-scheduled-effects> buildbot # [   51.533925] sshd-session[1647]: Accepted publickey for root from ::1 port 32856 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81361vm-test-run-scheduled-effects> buildbot # [   51.562656] sshd-session[1647]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1362vm-test-run-scheduled-effects> buildbot # [   51.574539] systemd-logind[970]: New session '6' of user 'root' with class 'user' and type 'tty'.1363vm-test-run-scheduled-effects> buildbot # [   51.579483] systemd[1]: Started Session 6 of User root.1364vm-test-run-scheduled-effects> buildbot # [   51.649128] sshd-session[1650]: Received disconnect from ::1 port 32856:11: disconnected by user1365vm-test-run-scheduled-effects> buildbot # [   51.652135] sshd-session[1650]: Disconnected from user root ::1 port 328561366vm-test-run-scheduled-effects> buildbot # [   51.654424] sshd-session[1647]: pam_unix(sshd:session): session closed for user root1367vm-test-run-scheduled-effects> buildbot # [   51.663101] systemd[1]: session-6.scope: Deactivated successfully.1368vm-test-run-scheduled-effects> buildbot # [   51.667643] systemd-logind[970]: Session 6 logged out. Waiting for processes to exit.1369vm-test-run-scheduled-effects> buildbot # [   51.672195] systemd-logind[970]: Removed session 6.1370vm-test-run-scheduled-effects> buildbot # [   51.689169] twistd[1419]: 2026-06-28T06:14:20+0000 [-] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']): command finished with signal None, exit code 0, elapsedTime: 0.4377771371vm-test-run-scheduled-effects> buildbot # [   51.697085] twistd[1419]: 2026-06-28T06:14:20+0000 [-] (command 5): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c9e0a50>1372vm-test-run-scheduled-effects> buildbot # [   51.703492] twistd[1418]: 2026-06-28T06:14:20+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'clone', '--branch', 'master', 'ssh://root@localhost/srv/repos/test-flake.git', '.', '--progress']'> rc=01373vm-test-run-scheduled-effects> buildbot # [   51.735882] twistd[1418]: 2026-06-28T06:14:20+0000 [-] <RemoteShellCommand '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']'>: RemoteCommand.run [6]1374vm-test-run-scheduled-effects> buildbot # [   51.741567] twistd[1418]: 2026-06-28T06:14:20+0000 [-] command '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']' in dir 'build'1375vm-test-run-scheduled-effects> buildbot # [   51.752109] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command 6): startCommand:shell1376vm-test-run-scheduled-effects> buildbot # [   51.754634] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']): RunProcess._startCommand1377vm-test-run-scheduled-effects> buildbot # [   51.761093] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']):  git -c 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"' checkout -f 1db2e9832193edc65e0de43ca6fed9b63bfb2d5b1378vm-test-run-scheduled-effects> buildbot # [   51.769619] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1379vm-test-run-scheduled-effects> buildbot # [   51.776440] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']):   watching logfiles {}1380vm-test-run-scheduled-effects> buildbot # [   51.783687] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']):   argv: [b'git', b'-c', b'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', b'checkout', b'-f', b'1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']1381vm-test-run-scheduled-effects> buildbot # [   51.792788] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']):   using PTY: False1382vm-test-run-scheduled-effects> buildbot # [   51.820217] twistd[1419]: 2026-06-28T06:14:20+0000 [-] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']): command finished with signal None, exit code 0, elapsedTime: 0.0375081383vm-test-run-scheduled-effects> buildbot # [   51.826857] twistd[1419]: 2026-06-28T06:14:20+0000 [-] (command 6): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c9e0f50>1384vm-test-run-scheduled-effects> buildbot # [   51.845104] twistd[1418]: 2026-06-28T06:14:20+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'checkout', '-f', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b']'> rc=01385vm-test-run-scheduled-effects> buildbot # [   51.879812] twistd[1418]: 2026-06-28T06:14:20+0000 [-] <RemoteShellCommand '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']'>: RemoteCommand.run [7]1386vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1387vm-test-run-scheduled-effects> buildbot # [   51.885481] twistd[1418]: 2026-06-28T06:14:20+0000 [-] command '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']' in dir 'build'1388vm-test-run-scheduled-effects> buildbot # [   51.894691] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command 7): startCommand:shell1389vm-test-run-scheduled-effects> buildbot # [   51.899049] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']): RunProcess._startCommand1390vm-test-run-scheduled-effects> buildbot # [   51.905291] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']):  git -c 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"' submodule update --init --recursive1391vm-test-run-scheduled-effects> buildbot # [   51.914404] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1392vm-test-run-scheduled-effects> buildbot # [   51.923756] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']):   watching logfiles {}1393vm-test-run-scheduled-effects> buildbot # [   51.929606] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']):   argv: [b'git', b'-c', b'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', b'submodule', b'update', b'--init', b'--recursive']1394vm-test-run-scheduled-effects> buildbot # [   51.938256] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']):   using PTY: False1395vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1396vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1397vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    401 100    401   0      0   6652      0                              0100    401 100    401   0      0   5325      0                              0100    401 100    401   0      0   4467      0                              01398vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.22 seconds)1399vm-test-run-scheduled-effects> buildbot # [   52.139207] twistd[1419]: 2026-06-28T06:14:20+0000 [-] (command ['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']): command finished with signal None, exit code 0, elapsedTime: 0.2169121400vm-test-run-scheduled-effects> buildbot # [   52.145835] twistd[1419]: 2026-06-28T06:14:20+0000 [-] (command 7): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c9869e0>1401vm-test-run-scheduled-effects> buildbot # [   52.152486] twistd[1418]: 2026-06-28T06:14:20+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['git', '-c', 'core.sshCommand=ssh -o "BatchMode=yes" -i "/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot/ssh-key"', 'submodule', 'update', '--init', '--recursive']'> rc=01402vm-test-run-scheduled-effects> buildbot # [   52.176995] twistd[1418]: 2026-06-28T06:14:20+0000 [-] <RemoteShellCommand '['git', 'rev-parse', 'HEAD']'>: RemoteCommand.run [8]1403vm-test-run-scheduled-effects> buildbot # [   52.179693] twistd[1418]: 2026-06-28T06:14:20+0000 [-] command '['git', 'rev-parse', 'HEAD']' in dir 'build'1404vm-test-run-scheduled-effects> buildbot # [   52.183085] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command 8): startCommand:shell1405vm-test-run-scheduled-effects> buildbot # [   52.188314] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']): RunProcess._startCommand1406vm-test-run-scheduled-effects> buildbot # [   52.191057] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):  git rev-parse HEAD1407vm-test-run-scheduled-effects> buildbot # [   52.193681] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1408vm-test-run-scheduled-effects> buildbot # [   52.197550] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):   watching logfiles {}1409vm-test-run-scheduled-effects> buildbot # [   52.200233] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):   argv: [b'git', b'rev-parse', b'HEAD']1410vm-test-run-scheduled-effects> buildbot # [   52.203259] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):   using PTY: False1411vm-test-run-scheduled-effects> buildbot # [   52.220660] twistd[1419]: 2026-06-28T06:14:20+0000 [-] (command ['git', 'rev-parse', 'HEAD']): command finished with signal None, exit code 0, elapsedTime: 0.0334221412vm-test-run-scheduled-effects> buildbot # [   52.224257] twistd[1419]: 2026-06-28T06:14:20+0000 [-] (command 8): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c986b10>1413vm-test-run-scheduled-effects> buildbot # [   52.251859] twistd[1418]: 2026-06-28T06:14:20+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['git', 'rev-parse', 'HEAD']'> rc=01414vm-test-run-scheduled-effects> buildbot # [   52.277577] twistd[1418]: 2026-06-28T06:14:20+0000 [-] Got Git revision 1db2e9832193edc65e0de43ca6fed9b63bfb2d5b1415vm-test-run-scheduled-effects> buildbot # [   52.280411] twistd[1418]: 2026-06-28T06:14:20+0000 [-] <RemoteCommand 'rmdir' at 128340373260560>: RemoteCommand.run [9]1416vm-test-run-scheduled-effects> buildbot # [   52.293095] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command 9): startCommand:rmdir1417vm-test-run-scheduled-effects> buildbot # [   52.295580] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']): RunProcess._startCommand1418vm-test-run-scheduled-effects> buildbot # [   52.300091] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']):  rm -rf /var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot1419vm-test-run-scheduled-effects> buildbot # [   52.304746] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']):   in dir /var/lib/buildbot-worker/worker-000 (timeout 120 secs)1420vm-test-run-scheduled-effects> buildbot # [   52.309121] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']):   watching logfiles {}1421vm-test-run-scheduled-effects> buildbot # [   52.314578] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']):   argv: [b'rm', b'-rf', b'/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']1422vm-test-run-scheduled-effects> buildbot # [   52.319610] twistd[1419]: 2026-06-28T06:14:20+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']):   using PTY: False1423vm-test-run-scheduled-effects> buildbot # [   52.339904] twistd[1419]: 2026-06-28T06:14:21+0000 [-] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']): command finished with signal None, exit code 0, elapsedTime: 0.0264391424vm-test-run-scheduled-effects> buildbot # [   52.344642] twistd[1419]: 2026-06-28T06:14:21+0000 [-] (command 9): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.fs.RemoveDirectory object at 0x739f6c9cb0e0>1425vm-test-run-scheduled-effects> buildbot # [   52.369074] twistd[1418]: 2026-06-28T06:14:21+0000 [Broker,0,127.0.0.1] <RemoteCommand 'rmdir' at 128340373260560> rc=01426vm-test-run-scheduled-effects> buildbot # [   52.393617] twistd[1418]: 2026-06-28T06:14:21+0000 [-] releaseLocks(GitLocalPrMerge(default_branch='master', repourl=Interpolate('ssh://root@localhost/srv/repos/test-flake.git'), method='clean', submodules=True, haltOnFailure=True, logEnviron=False, sshPrivateKey='-----BEGIN OPENSSH PRIVATE KEY-----\nb3BlbnNzaC1rZXktdjEAAAAABG5vbmUAAAAEbm9uZQAAAAAAAAABAAAAMwAAAAtzc2gtZW\nQyNTUxOQAAACBG+sEWLfMtuYxA4kvzcEgx8GkX6r7zt+hLnsiedIyX1wAAAJhFK1T9RStU\n/QAAAAtzc2gtZWQyNTUxOQAAACBG+sEWLfMtuYxA4kvzcEgx8GkX6r7zt+hLnsiedIyX1w\nAAAED1I5G8QWiUPUYhutClVIyCYqRZ3MYUj90NtABLcaSPZkb6wRYt8y25jEDiS/NwSDHw\naRfqvvO36EueyJ50jJfXAAAADnRlc3RAbG9jYWxob3N0AQIDBAUGBw==\n-----END OPENSSH PRIVATE KEY-----\n', sshKnownHosts=None)): []1427vm-test-run-scheduled-effects> buildbot # [   52.421931] twistd[1418]: 2026-06-28T06:14:21+0000 [-]  step 'git' complete: success (None)1428vm-test-run-scheduled-effects> buildbot # [   52.431805] twistd[1418]: 2026-06-28T06:14:21+0000 [-] acquireLocks(step NixEvalCommand(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x74b998228d70>, env={'CLICOLOR_FORCE': '1'}, name='Evaluate flake', nix_eval_config=NixEvalConfig(supported_systems=['x86_64-linux'], failed_build_report_limit=47, worker_count=1, max_memory_size=2048, eval_lock=<buildbot.locks.MasterLock object at 0x74b9982292b0>, gcroots_user='buildbot-worker', cache_failed_builds=False, show_trace=False), haltOnFailure=True, locks=[<buildbot.locks.LockAccess object at 0x74b99822a660>], drv_gcroots_dir=Interpolate('/nix/var/nix/gcroots/per-user/buildbot-worker/%(prop:project)s/drvs/%(prop:workername)s/'), logEnviron=False), locks [(<MasterLock(nix-eval, 1)>, <buildbot.locks.LockAccess object at 0x74b99822a660>)])1429vm-test-run-scheduled-effects> buildbot # [   52.455853] twistd[1418]: 2026-06-28T06:14:21+0000 [-] <RemoteShellCommand '['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']'>: RemoteCommand.run [10]1430vm-test-run-scheduled-effects> buildbot # [   52.459326] twistd[1418]: 2026-06-28T06:14:21+0000 [-] command '['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']' in dir 'build'1431vm-test-run-scheduled-effects> buildbot # [   52.463948] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command 10): startCommand:shell1432vm-test-run-scheduled-effects> buildbot # [   52.469096] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']): RunProcess._startCommand1433vm-test-run-scheduled-effects> buildbot # [   52.472611] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']):  sh -c 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi'1434vm-test-run-scheduled-effects> buildbot # [   52.476904] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1435vm-test-run-scheduled-effects> buildbot # [   52.481557] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']):   watching logfiles {}1436vm-test-run-scheduled-effects> buildbot # [   52.485049] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']):   argv: [b'sh', b'-c', b'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']1437vm-test-run-scheduled-effects> buildbot # [   52.489597] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']):   using PTY: False1438vm-test-run-scheduled-effects> buildbot # [   52.518271] twistd[1419]: 2026-06-28T06:14:21+0000 [-] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']): command finished with signal None, exit code 0, elapsedTime: 0.0499021439vm-test-run-scheduled-effects> buildbot # [   52.522698] twistd[1419]: 2026-06-28T06:14:21+0000 [-] (command 10): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6cfafe30>1440vm-test-run-scheduled-effects> buildbot # [   52.537117] twistd[1418]: 2026-06-28T06:14:21+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']'> rc=01441vm-test-run-scheduled-effects> buildbot # [   52.544716] twistd[1418]: 2026-06-28T06:14:21+0000 [-] <RemoteShellCommand '['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']'>: RemoteCommand.run [11]1442vm-test-run-scheduled-effects> buildbot # [   52.552519] twistd[1418]: 2026-06-28T06:14:21+0000 [-] command '['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']' in dir 'build'1443vm-test-run-scheduled-effects> buildbot # [   52.562106] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command 11): startCommand:shell1444vm-test-run-scheduled-effects> buildbot # [   52.564276] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']): RunProcess._startCommand1445vm-test-run-scheduled-effects> buildbot # [   52.571779] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']):  nix-eval-jobs --option eval-cache false --workers 1 --max-memory-size 2048 --option accept-flake-config true --gc-roots-dir /nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/ --force-recurse --check-cache-status --flake '.#checks'1446vm-test-run-scheduled-effects> buildbot # [   52.583506] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1447vm-test-run-scheduled-effects> buildbot # [   52.592300] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']):   watching logfiles {}1448vm-test-run-scheduled-effects> buildbot # [   52.601769] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']):   argv: [b'nix-eval-jobs', b'--option', b'eval-cache', b'false', b'--workers', b'1', b'--max-memory-size', b'2048', b'--option', b'accept-flake-config', b'true', b'--gc-roots-dir', b'/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', b'--force-recurse', b'--check-cache-status', b'--flake', b'.#checks']1449vm-test-run-scheduled-effects> buildbot # [   52.615582] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']):   using PTY: False1450vm-test-run-scheduled-effects> buildbot # [   52.783214] systemd[1]: Started Nix Daemon.1451vm-test-run-scheduled-effects> buildbot # [   52.921225] nix-daemon[1695]: accepted connection from pid 1694, user buildbot-worker1452vm-test-run-scheduled-effects> buildbot # [   52.956930] twistd[1419]: 2026-06-28T06:14:21+0000 [-] (command ['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']): command finished with signal None, exit code 0, elapsedTime: 0.3558901453vm-test-run-scheduled-effects> buildbot # [   52.966251] twistd[1419]: 2026-06-28T06:14:21+0000 [-] (command 11): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c9e89e0>1454vm-test-run-scheduled-effects> buildbot # [   52.973487] twistd[1418]: 2026-06-28T06:14:21+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['nix-eval-jobs', '--option', 'eval-cache', 'false', '--workers', '1', '--max-memory-size', '2048', '--option', 'accept-flake-config', 'true', '--gc-roots-dir', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/', '--force-recurse', '--check-cache-status', '--flake', '.#checks']'> rc=01455vm-test-run-scheduled-effects> buildbot # [   53.015147] twistd[1418]: 2026-06-28T06:14:21+0000 [-] releaseLocks(NixEvalCommand(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x74b998228d70>, env={'CLICOLOR_FORCE': '1'}, name='Evaluate flake', nix_eval_config=NixEvalConfig(supported_systems=['x86_64-linux'], failed_build_report_limit=47, worker_count=1, max_memory_size=2048, eval_lock=<buildbot.locks.MasterLock object at 0x74b9982292b0>, gcroots_user='buildbot-worker', cache_failed_builds=False, show_trace=False), haltOnFailure=True, locks=[<buildbot.locks.LockAccess object at 0x74b99822a660>], drv_gcroots_dir=Interpolate('/nix/var/nix/gcroots/per-user/buildbot-worker/%(prop:project)s/drvs/%(prop:workername)s/'), logEnviron=False)): [(<MasterLock(nix-eval, 1)>, <buildbot.locks.LockAccess object at 0x74b99822a660>)]1456vm-test-run-scheduled-effects> buildbot # [   53.036375] twistd[1418]: 2026-06-28T06:14:21+0000 [-]  step 'Evaluate flake' complete: success (None)1457vm-test-run-scheduled-effects> buildbot # [   53.065754] twistd[1418]: 2026-06-28T06:14:21+0000 [-] releaseLocks(BuildTrigger(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x74b998228d70>, trigger_config=TriggerConfig(builds_scheduler='test-flake-nix-build', failed_eval_scheduler='test-flake-nix-failed-eval', dependency_failed_scheduler='test-flake-nix-dependency-failed', cached_failure_scheduler='test-flake-nix-cached-failure'), jobs_config=JobsConfig(successful_jobs=[], failed_jobs=[], cache_failed_builds=False, failed_build_report_limit=47), nix_attr_prefix='checks', name='build flake')): []1458vm-test-run-scheduled-effects> buildbot # [   53.081788] twistd[1418]: 2026-06-28T06:14:21+0000 [-]  step 'build flake' complete: success (None)1459vm-test-run-scheduled-effects> buildbot # [   53.097148] twistd[1418]: 2026-06-28T06:14:21+0000 [-] releaseLocks(ProcessSkippedBuilds(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x74b998228d70>, gcroots_user='buildbot-worker', branch_config={}, outputs_path=None, name='Process skipped builds', doStepIf=<function nix_eval_config.<locals>.<lambda> at 0x74b998084ae0>, hideStepIf=<function nix_eval_config.<locals>.<lambda> at 0x74b998084b80>)): []1460vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1461vm-test-run-scheduled-effects> buildbot # [   53.110417] twistd[1418]: 2026-06-28T06:14:21+0000 [-]  step 'Process skipped builds' complete: skipped (None)1462vm-test-run-scheduled-effects> buildbot # [   53.133735] twistd[1418]: 2026-06-28T06:14:21+0000 [-] <RemoteShellCommand '['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']'>: RemoteCommand.run [12]1463vm-test-run-scheduled-effects> buildbot # [   53.137625] twistd[1418]: 2026-06-28T06:14:21+0000 [-] command '['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']' in dir 'build'1464vm-test-run-scheduled-effects> buildbot # [   53.141272] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command 12): startCommand:shell1465vm-test-run-scheduled-effects> buildbot # [   53.146144] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']): RunProcess._startCommand1466vm-test-run-scheduled-effects> buildbot # [   53.150171] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']):  rm -rf /nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/1467vm-test-run-scheduled-effects> buildbot # [   53.155269] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1468vm-test-run-scheduled-effects> buildbot # [   53.160316] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']):   watching logfiles {}1469vm-test-run-scheduled-effects> buildbot # [   53.165170] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']):   argv: [b'rm', b'-rf', b'/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']1470vm-test-run-scheduled-effects> buildbot # [   53.170648] twistd[1419]: 2026-06-28T06:14:21+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']):   using PTY: False1471vm-test-run-scheduled-effects> buildbot # [   53.191444] twistd[1419]: 2026-06-28T06:14:21+0000 [-] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']): command finished with signal None, exit code 0, elapsedTime: 0.0263041472vm-test-run-scheduled-effects> buildbot # [   53.196964] twistd[1419]: 2026-06-28T06:14:21+0000 [-] (command 12): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c9e8e20>1473vm-test-run-scheduled-effects> buildbot # [   53.224120] twistd[1418]: 2026-06-28T06:14:21+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']'> rc=01474vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1475vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1476vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0      [   53.279616] twistd[1418]: 2026-06-28T06:14:21+0000 [-] releaseLocks(ShellCommand(name='Cleanup drv paths', command=['rm', '-rf', Interpolate('/nix/var/nix/gcroots/per-user/buildbot-worker/%(prop:project)s/drvs/%(prop:workername)s/')], alwaysRun=True, logEnviron=False)): []1477vm-test-run-scheduled-effects> buildbot #                         0100    401 100    401   0[   53.300634] twistd[1418]: 2026-06-28T06:14:21+0000 [-]  step 'Cleanup drv paths' complete: success (None)1478vm-test-run-scheduled-effects> buildbot #       0   6083      0                              0100    401 100    401   0      0   4784      0                          [   53.330325] twistd[1418]: 2026-06-28T06:14:21+0000 [-] <RemoteShellCommand '['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']'>: RemoteCommand.run [13]1479vm-test-run-scheduled-effects> buildbot # [   53.334920] twistd[1418]: 2026-06-28T06:14:21+0000 [-] command '['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']' in dir 'build'1480vm-test-run-scheduled-effects> buildbot #     0100    401 100    401 [   53.347209] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command 13): startCommand:shell1481vm-test-run-scheduled-effects> buildbot # [   53.349425] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']): RunProcess._startCommand1482vm-test-run-scheduled-effects> buildbot # [   53.353884] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):  buildbot-effects list --rev 1db2e9832193edc65e0de43ca6fed9b63bfb2d5b --branch master --repo test-flake1483vm-test-run-scheduled-effects> buildbot # [   53.359665] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1484vm-test-run-scheduled-effects> buildbot # [   53.365276] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):   watching logfiles {}1485vm-test-run-scheduled-effects> buildbot # [   53.369685] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):   argv: [b'buildbot-effects', b'list', b'--rev', b'1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', b'--branch', b'master', b'--repo', b'test-flake']1486vm-test-run-scheduled-effects> buildbot # [   53.376299] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):   using PTY: False1487vm-test-run-scheduled-effects> buildbot #   0      0   3594      0                              01488vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.29 seconds)1489vm-test-run-scheduled-effects> buildbot # [   53.805112] nix-daemon[1695]: accepted connection from pid 1707, user buildbot-worker1490vm-test-run-scheduled-effects> buildbot # [   53.842617] twistd[1419]: 2026-06-28T06:14:22+0000 [-] (command ['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']): command finished with signal None, exit code 0, elapsedTime: 0.4983021491vm-test-run-scheduled-effects> buildbot # [   53.848105] twistd[1419]: 2026-06-28T06:14:22+0000 [-] (command 13): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c9f8450>1492vm-test-run-scheduled-effects> buildbot # [   53.855132] twistd[1418]: 2026-06-28T06:14:22+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['buildbot-effects', 'list', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']'> rc=01493vm-test-run-scheduled-effects> buildbot # [   53.898346] twistd[1418]: 2026-06-28T06:14:22+0000 [-] releaseLocks(BuildbotEffectsCommand(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x74b998228d70>, env={}, name='Evaluate effects', command=['buildbot-effects', 'list', '--rev', Property(revision), '--branch', Property(branch), '--repo', Property(project)], flunkOnFailure=True, doStepIf=<function nix_eval_config.<locals>.<lambda> at 0x74b998085300>, logEnviron=False)): []1494vm-test-run-scheduled-effects> buildbot # [   53.912991] twistd[1418]: 2026-06-28T06:14:22+0000 [-]  step 'Evaluate effects' complete: success (None)1495vm-test-run-scheduled-effects> buildbot # [   53.929787] twistd[1418]: 2026-06-28T06:14:22+0000 [-] releaseLocks(BuildbotEffectsTrigger(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x74b998228d70>, effects_scheduler='test-flake-run-effect', name='Buildbot effect', effects=[])): []1496vm-test-run-scheduled-effects> buildbot # [   54.030467] twistd[1418]: 2026-06-28T06:14:22+0000 [-]  step 'Buildbot effect' complete: success (None)1497vm-test-run-scheduled-effects> buildbot # [   54.047137] twistd[1418]: 2026-06-28T06:14:22+0000 [-] <RemoteShellCommand '['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']'>: RemoteCommand.run [14]1498vm-test-run-scheduled-effects> buildbot # [   54.051872] twistd[1418]: 2026-06-28T06:14:22+0000 [-] command '['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']' in dir 'build'1499vm-test-run-scheduled-effects> buildbot # [   54.058973] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command 14): startCommand:shell1500vm-test-run-scheduled-effects> buildbot # [   54.061871] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']): RunProcess._startCommand1501vm-test-run-scheduled-effects> buildbot # [   54.066719] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):  buildbot-effects list-schedules --rev 1db2e9832193edc65e0de43ca6fed9b63bfb2d5b --branch master --repo test-flake1502vm-test-run-scheduled-effects> buildbot # [   54.073234] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1503vm-test-run-scheduled-effects> buildbot # [   54.080976] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):   watching logfiles {}1504vm-test-run-scheduled-effects> buildbot # [   54.085650] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):   argv: [b'buildbot-effects', b'list-schedules', b'--rev', b'1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', b'--branch', b'master', b'--repo', b'test-flake']1505vm-test-run-scheduled-effects> buildbot # [   54.092545] twistd[1419]: 2026-06-28T06:14:22+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']):   using PTY: False1506vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1507vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1508vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1509vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    401 100    401   0      0   6454      0                              0100    401 100    401   0      0   5257      0                              0100    401 100    401   0      0   4366      0                              0[   54.567220] nix-daemon[1695]: accepted connection from pid 1716, user buildbot-worker1510vm-test-run-scheduled-effects> buildbot # 1511vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.18 seconds)1512vm-test-run-scheduled-effects> buildbot # [   54.616369] twistd[1419]: 2026-06-28T06:14:23+0000 [-] (command ['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']): command finished with signal None, exit code 0, elapsedTime: 0.5358051513vm-test-run-scheduled-effects> buildbot # [   54.622132] twistd[1419]: 2026-06-28T06:14:23+0000 [-] (command 14): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x739f6c9f8750>1514vm-test-run-scheduled-effects> buildbot # [   54.630142] twistd[1418]: 2026-06-28T06:14:23+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['buildbot-effects', 'list-schedules', '--rev', '1db2e9832193edc65e0de43ca6fed9b63bfb2d5b', '--branch', 'master', '--repo', 'test-flake']'> rc=01515vm-test-run-scheduled-effects> buildbot # [   54.690378] twistd[1418]: 2026-06-28T06:14:23+0000 [-] releaseLocks(ScheduledEffectsEvaluateCommand(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x74b998228d70>, schedules_cache_file='/var/lib/buildbot/scheduled-effects-cache/test-flake-schedules.json', env={}, name='Evaluate scheduled effects', command=['buildbot-effects', 'list-schedules', '--rev', Property(revision), '--branch', Property(branch), '--repo', Property(project)], flunkOnFailure=False, warnOnFailure=True, alwaysRun=True, doStepIf=<function nix_eval_config.<locals>.<lambda> at 0x74b9980854e0>, hideStepIf=<function nix_eval_config.<locals>.<lambda> at 0x74b998085580>, logEnviron=False)): []1516vm-test-run-scheduled-effects> buildbot # [   54.712521] twistd[1418]: 2026-06-28T06:14:23+0000 [-]  step 'Evaluate scheduled effects' complete: success (None)1517vm-test-run-scheduled-effects> buildbot # [   54.715147] twistd[1418]: 2026-06-28T06:14:23+0000 [-]  <Build test-flake/nix-eval number:1 results:success>: build finished1518vm-test-run-scheduled-effects> buildbot # [   54.727965] twistd[1418]: 2026-06-28T06:14:23+0000 [-] releaseLocks(<Worker 'local-worker-000'>): []1519vm-test-run-scheduled-effects> buildbot # [   54.895813] sshd-session[1728]: Accepted publickey for root from ::1 port 53772 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81520vm-test-run-scheduled-effects> buildbot # [   54.913580] sshd-session[1728]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1521vm-test-run-scheduled-effects> buildbot # [   54.925375] systemd-logind[970]: New session '7' of user 'root' with class 'user' and type 'tty'.1522vm-test-run-scheduled-effects> buildbot # [   54.930476] systemd[1]: Started Session 7 of User root.1523vm-test-run-scheduled-effects> buildbot # [   54.978789] sshd-session[1735]: Received disconnect from ::1 port 53772:11: disconnected by user1524vm-test-run-scheduled-effects> buildbot # [   54.981159] sshd-session[1735]: Disconnected from user root ::1 port 537721525vm-test-run-scheduled-effects> buildbot # [   54.983341] sshd-session[1728]: pam_unix(sshd:session): session closed for user root1526vm-test-run-scheduled-effects> buildbot # [   54.999355] systemd[1]: session-7.scope: Deactivated successfully.1527vm-test-run-scheduled-effects> buildbot # [   55.003259] systemd-logind[970]: Session 7 logged out. Waiting for processes to exit.1528vm-test-run-scheduled-effects> buildbot # [   55.006121] systemd-logind[970]: Removed session 7.1529vm-test-run-scheduled-effects> buildbot # [   55.232816] sshd-session[1740]: Accepted publickey for root from ::1 port 53776 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81530vm-test-run-scheduled-effects> buildbot # [   55.261934] sshd-session[1740]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1531vm-test-run-scheduled-effects> buildbot # [   55.274190] systemd-logind[970]: New session '8' of user 'root' with class 'user' and type 'tty'.1532vm-test-run-scheduled-effects> buildbot # [   55.280074] systemd[1]: Started Session 8 of User root.1533vm-test-run-scheduled-effects> buildbot # [   55.338278] sshd-session[1743]: Received disconnect from ::1 port 53776:11: disconnected by user1534vm-test-run-scheduled-effects> buildbot # [   55.340643] sshd-session[1743]: Disconnected from user root ::1 port 537761535vm-test-run-scheduled-effects> buildbot # [   55.342664] sshd-session[1740]: pam_unix(sshd:session): session closed for user root1536vm-test-run-scheduled-effects> buildbot # [   55.351729] systemd[1]: session-8.scope: Deactivated successfully.1537vm-test-run-scheduled-effects> buildbot # [   55.358901] systemd-logind[970]: Session 8 logged out. Waiting for processes to exit.1538vm-test-run-scheduled-effects> buildbot # [   55.362552] systemd-logind[970]: Removed session 8.1539vm-test-run-scheduled-effects> buildbot # [   55.366453] twistd[1418]: 2026-06-28T06:14:24+0000 [-] gitpoller: processing changes from "ssh://root@localhost/srv/repos/test-flake.git"1540vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1541vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1542vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1543vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    411 100    411   0      0  10644      0                              0100    411 100    411   0      0   8343      0                              0100    411 100    411   0      0   6920      0                              01544vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1545vm-test-run-scheduled-effects> (finished: subtest: Wait for nix-eval build to complete, in 19.09 seconds)1546vm-test-run-scheduled-effects> subtest: Schedule cache is created1547vm-test-run-scheduled-effects> buildbot: waiting for success: test -f /var/lib/buildbot/scheduled-effects-cache/test-flake-schedules.json1548vm-test-run-scheduled-effects> buildbot: (finished: waiting for success: test -f /var/lib/buildbot/scheduled-effects-cache/test-flake-schedules.json, in 0.03 seconds)1549vm-test-run-scheduled-effects> buildbot: must succeed: cat /var/lib/buildbot/scheduled-effects-cache/test-flake-schedules.json1550vm-test-run-scheduled-effects> buildbot: (finished: must succeed: cat /var/lib/buildbot/scheduled-effects-cache/test-flake-schedules.json, in 0.04 seconds)1551vm-test-run-scheduled-effects> (finished: subtest: Schedule cache is created, in 0.07 seconds)1552vm-test-run-scheduled-effects> subtest: Nightly schedulers are created1553vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1554vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1555vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1556vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   3793 100   3793   0      0  44278      0                              0100   3793 100   3793   0      0  39237      0                              0100   3793 100   3793   0      0  35489      0                              01557vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.18 seconds)1558vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1559vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1560vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1561vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   3793 100   3793   0      0  36755      0                              0100   3793 100   3793   0      0  33263      0                              0100   3793 100   3793   0      0  30500      0                              01562vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.23 seconds)1563vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1564vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1565vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1566vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   3793 100   3793   0      0  40566      0                              0100   3793 100   3793   0      0  35587      0                              0100   3793 100   3793   0      0  32555      0                              01567vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.21 seconds)1568vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1569vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1570vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1571vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   3793 100   3793   0      0  38832      0                              0100   3793 100   3793   0      0  35085      0                              0100   3793 100   3793   0      0  32088      0                              01572vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.22 seconds)1573vm-test-run-scheduled-effects> buildbot # [   59.683308] twistd[1418]: 2026-06-28T06:14:28+0000 [buildbot_nix.nix_eval#info] Triggering reconfig due to schedule changes in test-flake1574vm-test-run-scheduled-effects> buildbot # [   59.686494] twistd[1418]: 2026-06-28T06:14:28+0000 [-] beginning configuration update1575vm-test-run-scheduled-effects> buildbot # [   59.689497] twistd[1418]: 2026-06-28T06:14:28+0000 [-] Loading configuration from '/nix/store/lrw01m59h52qsb3jnqd1wm6qfaj4z4sv-master.cfg'1576vm-test-run-scheduled-effects> buildbot # [   59.717129] twistd[1418]: 2026-06-28T06:14:28+0000 [-] gitpoller: using workdir '/var/lib/buildbot/master/gitpoller-work'1577vm-test-run-scheduled-effects> buildbot # [   59.722177] twistd[1418]: 2026-06-28T06:14:28+0000 [-] adding 1 new schedulers, removing 01578vm-test-run-scheduled-effects> buildbot # [   59.836826] twistd[1418]: 2026-06-28T06:14:28+0000 [-] configuration update complete (took 0.154 seconds)1579vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1580vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1581vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1582vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   4079 100   4079   0      0  38053      0                              0100   4079 100   4079   0      0  34758      0                              0100   4079 100   4079   0      0  31997      0                              01583vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.23 seconds)1584vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1585vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1586vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1587vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   4079 100   4079   0      0  39719      0                              0100   4079 100   4079   0      0  35959      0                              0100   4079 100   4079   0      0  32980      0                              01588vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.20 seconds)1589vm-test-run-scheduled-effects> (finished: subtest: Nightly schedulers are created, in 5.25 seconds)1590vm-test-run-scheduled-effects> subtest: Scheduled effect builder exists1591vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builders1592vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1593vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1594vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   2371 100   2371   0      0  58304      0                              0100   2371 100   2371   0      0  46209      0                              0100   2371 100   2371   0      0  38464      0                              01595vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builders, in 0.14 seconds)1596vm-test-run-scheduled-effects> (finished: subtest: Scheduled effect builder exists, in 0.14 seconds)1597vm-test-run-scheduled-effects> (finished: run the VM test script, in 62.46 seconds)1598vm-test-run-scheduled-effects> test script finished in 62.52s1599vm-test-run-scheduled-effects> cleanup1600vm-test-run-scheduled-effects> kill QemuMachine (pid 12)1601vm-test-run-scheduled-effects> buildbot # qemu-system-x86_64: terminating on signal 15 from pid 6 (/nix/store/60m4rxhg2fldqaak400c0lry96ijrzqn-python3-3.13.13/bin/python3.13)1602vm-test-run-scheduled-effects> (finished: cleanup, in 0.20 seconds)16031604post-build step Upload coverage to codecov: ok1605Skipping codecov: project=nix-community/buildbot-nix attr=x86_64-linux.scheduled-effects