nixbot

1these 12 derivations will be built:2  /nix/store/hv9lpqc2plfz3sbsjw5i3nn082dk4y97-unit-script-setup-git-repo-start.drv3  /nix/store/4va2d61zsl1yba4v2dw5n3wma65gljn4-unit-setup-git-repo.service.drv4  /nix/store/kf53fqwvhx2rjss000bl7hc5bkbhhxlm-system-units.drv5  /nix/store/ql090j0iyrqn4c4fzh4vhjjcd743gbhr-etc.drv6  /nix/store/8fahhasihwh95vwrq2c7ly53iyxndpc6-activate.drv7  /nix/store/q899682zafsdc44lnnz62h259ynvzjpi-nixos-system-buildbot-test.drv8  /nix/store/fqqxylaqb1vxq5di177hgj579xfhjfqz-closure-info.drv9  /nix/store/s9a88kd2nri04ywn98gkap7988lbq4fm-run-nixos-vm.drv10  /nix/store/qi837c8869pb0pv7gzm1jh1wbhs7i98z-nixos-vm.drv11  /nix/store/bcdgpnpk8nam00r5krvba357lzninkg8-driverConfiguration.json.drv12  /nix/store/mm10cmvkvyh08nizg4pwyldmswswgywz-nixos-test-driver-scheduled-effects.drv13  /nix/store/hpxn3iz94h84j2qn7rrz6id48m27gyvv-vm-test-run-scheduled-effects.drv14building '/nix/store/hv9lpqc2plfz3sbsjw5i3nn082dk4y97-unit-script-setup-git-repo-start.drv'15building '/nix/store/4va2d61zsl1yba4v2dw5n3wma65gljn4-unit-setup-git-repo.service.drv'16building '/nix/store/kf53fqwvhx2rjss000bl7hc5bkbhhxlm-system-units.drv'17building '/nix/store/ql090j0iyrqn4c4fzh4vhjjcd743gbhr-etc.drv'18building '/nix/store/8fahhasihwh95vwrq2c7ly53iyxndpc6-activate.drv'19building '/nix/store/q899682zafsdc44lnnz62h259ynvzjpi-nixos-system-buildbot-test.drv'20nixos-system-buildbot-test> structuredAttrs is enabled21building '/nix/store/fqqxylaqb1vxq5di177hgj579xfhjfqz-closure-info.drv'22closure-info> structuredAttrs is enabled23building '/nix/store/s9a88kd2nri04ywn98gkap7988lbq4fm-run-nixos-vm.drv'24building '/nix/store/qi837c8869pb0pv7gzm1jh1wbhs7i98z-nixos-vm.drv'25building '/nix/store/bcdgpnpk8nam00r5krvba357lzninkg8-driverConfiguration.json.drv'26driverConfiguration.json> structuredAttrs is enabled27building '/nix/store/mm10cmvkvyh08nizg4pwyldmswswgywz-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/hpxn3iz94h84j2qn7rrz6id48m27gyvv-vm-test-run-scheduled-effects.drv' on 'ssh-ng://nix@jamie'35building '/nix/store/hpxn3iz94h84j2qn7rrz6id48m27gyvv-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.00 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 # Disk image does not exist, creating the virtualisation disk image...49vm-test-run-scheduled-effects> buildbot: QEMU running (pid 12)50vm-test-run-scheduled-effects> buildbot # Formatting '/build/vm-state-buildbot/tmp.9MOt4MmxBB', 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: c0818cc1-35ca-43f0-84eb-d807714be83255vm-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.33 (nixbld@localhost) (gcc (GCC) 15.2.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT_DYNAMIC Sat May 23 11:07:21 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/hp7z2p822q6306mrr7j6dc5c3m0bgp0s-nixos-system-buildbot-test/init regInfo=/nix/store/r27mxz7ix4akpv9qg9blwnwk3vza4d5v-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.000000] kvm-clock: using sched offset of 563598541 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.008 MHz processor100vm-test-run-scheduled-effects> buildbot # [    0.000812] last_pfn = 0x3ffdb max_arch_pfn = 0x10000000000101vm-test-run-scheduled-effects> buildbot # [    0.000848] MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs102vm-test-run-scheduled-effects> buildbot # [    0.000850] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT103vm-test-run-scheduled-effects> buildbot # [    0.002763] found SMP MP-table at [mem 0x000f5470-0x000f547f]104vm-test-run-scheduled-effects> buildbot # [    0.002774] Using GB pages for direct mapping105vm-test-run-scheduled-effects> buildbot # [    0.002827] RAMDISK: [mem 0x3e4f0000-0x3ffcffff]106vm-test-run-scheduled-effects> buildbot # [    0.002835] ACPI: Early table checksum verification disabled107vm-test-run-scheduled-effects> buildbot # [    0.002838] ACPI: RSDP 0x00000000000F5290 000014 (v00 BOCHS )108vm-test-run-scheduled-effects> buildbot # [    0.002841] ACPI: RSDT 0x000000003FFE23D9 000034 (v01 BOCHS  BXPC     00000001 BXPC 00000001)109vm-test-run-scheduled-effects> buildbot # [    0.002845] ACPI: FACP 0x000000003FFE228D 000074 (v01 BOCHS  BXPC     00000001 BXPC 00000001)110vm-test-run-scheduled-effects> buildbot # [    0.002852] ACPI: DSDT 0x000000003FFE0040 00224D (v01 BOCHS  BXPC     00000001 BXPC 00000001)111vm-test-run-scheduled-effects> buildbot # [    0.002854] ACPI: FACS 0x000000003FFE0000 000040112vm-test-run-scheduled-effects> buildbot # [    0.002855] ACPI: APIC 0x000000003FFE2301 000078 (v03 BOCHS  BXPC     00000001 BXPC 00000001)113vm-test-run-scheduled-effects> buildbot # [    0.002857] ACPI: HPET 0x000000003FFE2379 000038 (v01 BOCHS  BXPC     00000001 BXPC 00000001)114vm-test-run-scheduled-effects> buildbot # [    0.002858] ACPI: WAET 0x000000003FFE23B1 000028 (v01 BOCHS  BXPC     00000001 BXPC 00000001)115vm-test-run-scheduled-effects> buildbot # [    0.002860] ACPI: Reserving FACP table memory at [mem 0x3ffe228d-0x3ffe2300]116vm-test-run-scheduled-effects> buildbot # [    0.002860] ACPI: Reserving DSDT table memory at [mem 0x3ffe0040-0x3ffe228c]117vm-test-run-scheduled-effects> buildbot # [    0.002861] ACPI: Reserving FACS table memory at [mem 0x3ffe0000-0x3ffe003f]118vm-test-run-scheduled-effects> buildbot # [    0.002862] ACPI: Reserving APIC table memory at [mem 0x3ffe2301-0x3ffe2378]119vm-test-run-scheduled-effects> buildbot # [    0.002862] ACPI: Reserving HPET table memory at [mem 0x3ffe2379-0x3ffe23b0]120vm-test-run-scheduled-effects> buildbot # [    0.002862] ACPI: Reserving WAET table memory at [mem 0x3ffe23b1-0x3ffe23d8]121vm-test-run-scheduled-effects> buildbot # [    0.003351] No NUMA configuration found122vm-test-run-scheduled-effects> buildbot # [    0.003353] Faking a node at [mem 0x0000000000000000-0x000000003ffdafff]123vm-test-run-scheduled-effects> buildbot # [    0.003356] NODE_DATA(0) allocated [mem 0x3ffd5780-0x3ffdacff]124vm-test-run-scheduled-effects> buildbot # [    0.006310] Zone ranges:125vm-test-run-scheduled-effects> buildbot # [    0.006310]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]126vm-test-run-scheduled-effects> buildbot # [    0.006312]   DMA32    [mem 0x0000000001000000-0x000000003ffdafff]127vm-test-run-scheduled-effects> buildbot # [    0.006313]   Normal   empty128vm-test-run-scheduled-effects> buildbot # [    0.006314]   Device   empty129vm-test-run-scheduled-effects> buildbot # [    0.006315] Movable zone start for each node130vm-test-run-scheduled-effects> buildbot # [    0.006316] Early memory node ranges131vm-test-run-scheduled-effects> buildbot # [    0.006316]   node   0: [mem 0x0000000000001000-0x000000000009efff]132vm-test-run-scheduled-effects> buildbot # [    0.006317]   node   0: [mem 0x0000000000100000-0x000000003ffdafff]133vm-test-run-scheduled-effects> buildbot # [    0.006318] Initmem setup node 0 [mem 0x0000000000001000-0x000000003ffdafff]134vm-test-run-scheduled-effects> buildbot # [    0.006395] On node 0, zone DMA: 1 pages in unavailable ranges135vm-test-run-scheduled-effects> buildbot # [    0.006680] On node 0, zone DMA: 97 pages in unavailable ranges136vm-test-run-scheduled-effects> buildbot # [    0.025915] On node 0, zone DMA32: 37 pages in unavailable ranges137vm-test-run-scheduled-effects> buildbot # [    0.026902] ACPI: PM-Timer IO Port: 0x608138vm-test-run-scheduled-effects> buildbot # [    0.026916] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])139vm-test-run-scheduled-effects> buildbot # [    0.026948] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23140vm-test-run-scheduled-effects> buildbot # [    0.026951] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)141vm-test-run-scheduled-effects> buildbot # [    0.026953] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)142vm-test-run-scheduled-effects> buildbot # [    0.026954] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)143vm-test-run-scheduled-effects> buildbot # [    0.026955] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)144vm-test-run-scheduled-effects> buildbot # [    0.026956] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)145vm-test-run-scheduled-effects> buildbot # [    0.026958] ACPI: Using ACPI (MADT) for SMP configuration information146vm-test-run-scheduled-effects> buildbot # [    0.026959] ACPI: HPET id: 0x8086a201 base: 0xfed00000147vm-test-run-scheduled-effects> buildbot # [    0.026963] TSC deadline timer available148vm-test-run-scheduled-effects> buildbot # [    0.026967] CPU topo: Max. logical packages:   1149vm-test-run-scheduled-effects> buildbot # [    0.026968] CPU topo: Max. logical dies:       1150vm-test-run-scheduled-effects> buildbot # [    0.026968] CPU topo: Max. dies per package:   1151vm-test-run-scheduled-effects> buildbot # [    0.026972] CPU topo: Max. threads per core:   1152vm-test-run-scheduled-effects> buildbot # [    0.026973] CPU topo: Num. cores per package:     1153vm-test-run-scheduled-effects> buildbot # [    0.026973] CPU topo: Num. threads per package:   1154vm-test-run-scheduled-effects> buildbot # [    0.026973] CPU topo: Allowing 1 present CPUs plus 0 hotplug CPUs155vm-test-run-scheduled-effects> buildbot # [    0.026992] kvm-guest: APIC: eoi() replaced with kvm_guest_apic_eoi_write()156vm-test-run-scheduled-effects> buildbot # [    0.027026] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]157vm-test-run-scheduled-effects> buildbot # [    0.027028] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x000fffff]158vm-test-run-scheduled-effects> buildbot # [    0.027029] [mem 0x40000000-0xfeffbfff] available for PCI devices159vm-test-run-scheduled-effects> buildbot # [    0.027031] Booting paravirtualized kernel on KVM160vm-test-run-scheduled-effects> buildbot # [    0.027033] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns161vm-test-run-scheduled-effects> buildbot # [    0.031485] setup_percpu: NR_CPUS:384 nr_cpumask_bits:1 nr_cpu_ids:1 nr_node_ids:1162vm-test-run-scheduled-effects> buildbot # [    0.033703] percpu: Embedded 98 pages/cpu s278528 r8192 d114688 u2097152163vm-test-run-scheduled-effects> buildbot # [    0.033749] kvm-guest: PV spinlocks disabled, single CPU164vm-test-run-scheduled-effects> buildbot # [    0.033751] 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/hp7z2p822q6306mrr7j6dc5c3m0bgp0s-nixos-system-buildbot-test/init regInfo=/nix/store/r27mxz7ix4akpv9qg9blwnwk3vza4d5v-closure-info/registration console=ttyS0,115200n8 console=tty0165vm-test-run-scheduled-effects> buildbot # [    0.033840] Unknown kernel command line parameters "regInfo=/nix/store/r27mxz7ix4akpv9qg9blwnwk3vza4d5v-closure-info/registration", will be passed to user space.166vm-test-run-scheduled-effects> buildbot # [    0.033853] random: crng init done167vm-test-run-scheduled-effects> buildbot # [    0.033853] printk: log buffer data + meta data: 262144 + 917504 = 1179648 bytes168vm-test-run-scheduled-effects> buildbot # [    0.033874] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)169vm-test-run-scheduled-effects> buildbot # [    0.034432] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes, linear)170vm-test-run-scheduled-effects> buildbot # [    0.034463] Fallback order for Node 0: 0171vm-test-run-scheduled-effects> buildbot # [    0.034466] Built 1 zonelists, mobility grouping on.  Total pages: 262009172vm-test-run-scheduled-effects> buildbot # [    0.034467] Policy zone: DMA32173vm-test-run-scheduled-effects> buildbot # [    0.036992] mem auto-init: stack:all(zero), heap alloc:on, heap free:off174vm-test-run-scheduled-effects> buildbot # [    0.039325] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1175vm-test-run-scheduled-effects> buildbot # [    0.041823] allocated 2097152 bytes of page_ext176vm-test-run-scheduled-effects> buildbot # [    0.051412] ftrace: allocating 48552 entries in 192 pages177vm-test-run-scheduled-effects> buildbot # [    0.051414] ftrace: allocated 192 pages with 2 groups178vm-test-run-scheduled-effects> buildbot # [    0.052263] Dynamic Preempt: lazy179vm-test-run-scheduled-effects> buildbot # [    0.052437] rcu: Preemptible hierarchical RCU implementation.180vm-test-run-scheduled-effects> buildbot # [    0.052437] rcu: 	RCU event tracing is enabled.181vm-test-run-scheduled-effects> buildbot # [    0.052438] rcu: 	RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=1.182vm-test-run-scheduled-effects> buildbot # [    0.052440] 	Trampoline variant of Tasks RCU enabled.183vm-test-run-scheduled-effects> buildbot # [    0.052440] 	Rude variant of Tasks RCU enabled.184vm-test-run-scheduled-effects> buildbot # [    0.052440] 	Tracing variant of Tasks RCU enabled.185vm-test-run-scheduled-effects> buildbot # [    0.052441] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.186vm-test-run-scheduled-effects> buildbot # [    0.052442] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1187vm-test-run-scheduled-effects> buildbot # [    0.052466] 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.052467] 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.052468] 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.056811] NR_IRQS: 24832, nr_irqs: 256, preallocated irqs: 16191vm-test-run-scheduled-effects> buildbot # [    0.057079] rcu: srcu_init: Setting srcu_struct sizes based on contention.192vm-test-run-scheduled-effects> buildbot # [    0.057183] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)193vm-test-run-scheduled-effects> buildbot # [    0.064285] Console: colour VGA+ 80x25194vm-test-run-scheduled-effects> buildbot # [    0.064289] printk: legacy console [tty0] enabled195vm-test-run-scheduled-effects> buildbot # [    0.104710] printk: legacy console [ttyS0] enabled196vm-test-run-scheduled-effects> buildbot # [    0.291712] ACPI: Core revision 20250807197vm-test-run-scheduled-effects> buildbot # [    0.293255] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns198vm-test-run-scheduled-effects> buildbot # [    0.296028] APIC: Switch to symmetric I/O mode setup199vm-test-run-scheduled-effects> buildbot # [    0.297767] x2apic enabled200vm-test-run-scheduled-effects> buildbot # [    0.298991] APIC: Switched APIC routing to: physical x2apic201vm-test-run-scheduled-effects> buildbot # [    0.301808] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1202vm-test-run-scheduled-effects> buildbot # [    0.303628] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983f10a64, max_idle_ns: 440795218721 ns203vm-test-run-scheduled-effects> buildbot # [    0.306706] Calibrating delay loop (skipped) preset value.. 4800.01 BogoMIPS (lpj=2400008)204vm-test-run-scheduled-effects> buildbot # [    0.308818] x86/cpu: User Mode Instruction Prevention (UMIP) activated205vm-test-run-scheduled-effects> buildbot # [    0.309866] Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127206vm-test-run-scheduled-effects> buildbot # [    0.310705] Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0207vm-test-run-scheduled-effects> buildbot # [    0.311709] mitigations: Enabled attack vectors: user_kernel, user_user, guest_host, guest_guest, SMT mitigations: auto208vm-test-run-scheduled-effects> buildbot # [    0.312705] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl209vm-test-run-scheduled-effects> buildbot # [    0.313705] Spectre V2 : Mitigation: Enhanced / Automatic IBRS210vm-test-run-scheduled-effects> buildbot # [    0.315705] Speculative Return Stack Overflow: Mitigation: Safe RET211vm-test-run-scheduled-effects> buildbot # [    0.317705] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization212vm-test-run-scheduled-effects> buildbot # [    0.319710] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier213vm-test-run-scheduled-effects> buildbot # [    0.320706] active return thunk: srso_alias_return_thunk214vm-test-run-scheduled-effects> buildbot # [    0.322730] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'215vm-test-run-scheduled-effects> buildbot # [    0.323705] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'216vm-test-run-scheduled-effects> buildbot # [    0.325705] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'217vm-test-run-scheduled-effects> buildbot # [    0.327705] x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask'218vm-test-run-scheduled-effects> buildbot # [    0.329705] x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256'219vm-test-run-scheduled-effects> buildbot # [    0.330705] x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256'220vm-test-run-scheduled-effects> buildbot # [    0.331705] x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers'221vm-test-run-scheduled-effects> buildbot # [    0.333706] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256222vm-test-run-scheduled-effects> buildbot # [    0.335705] x86/fpu: xstate_offset[5]:  832, xstate_sizes[5]:   64223vm-test-run-scheduled-effects> buildbot # [    0.337705] x86/fpu: xstate_offset[6]:  896, xstate_sizes[6]:  512224vm-test-run-scheduled-effects> buildbot # [    0.338705] x86/fpu: xstate_offset[7]: 1408, xstate_sizes[7]: 1024225vm-test-run-scheduled-effects> buildbot # [    0.339705] x86/fpu: xstate_offset[9]: 2432, xstate_sizes[9]:    8226vm-test-run-scheduled-effects> buildbot # [    0.340706] x86/fpu: Enabled xstate features 0x2e7, context size is 2440 bytes, using 'compacted' format.227vm-test-run-scheduled-effects> buildbot # [    0.375514] Freeing SMP alternatives memory: 44K228vm-test-run-scheduled-effects> buildbot # [    0.376714] pid_max: default: 32768 minimum: 301229vm-test-run-scheduled-effects> buildbot # [    0.377825] LSM: initializing lsm=capability,landlock,yama,bpf,ima230vm-test-run-scheduled-effects> buildbot # [    0.379816] landlock: Up and running.231vm-test-run-scheduled-effects> buildbot # [    0.381705] Yama: becoming mindful.232vm-test-run-scheduled-effects> buildbot # [    0.382924] LSM support for eBPF active233vm-test-run-scheduled-effects> buildbot # [    0.383809] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)234vm-test-run-scheduled-effects> buildbot # [    0.385732] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)235vm-test-run-scheduled-effects> buildbot # [    0.389117] smpboot: CPU0: AMD EPYC 9654 96-Core Processor (family: 0x19, model: 0x11, stepping: 0x1)236vm-test-run-scheduled-effects> buildbot # [    0.390383] Performance Events: Fam17h+ core perfctr, AMD PMU driver.237vm-test-run-scheduled-effects> buildbot # [    0.391740] ... version:                   2238vm-test-run-scheduled-effects> buildbot # [    0.392707] ... bit width:                 48239vm-test-run-scheduled-effects> buildbot # [    0.393707] ... generic counters:          6240vm-test-run-scheduled-effects> buildbot # [    0.394707] ... generic bitmap:            000000000000003f241vm-test-run-scheduled-effects> buildbot # [    0.395707] ... fixed-purpose counters:    0242vm-test-run-scheduled-effects> buildbot # [    0.396707] ... fixed-purpose bitmap:      0000000000000000243vm-test-run-scheduled-effects> buildbot # [    0.397707] ... value mask:                0000ffffffffffff244vm-test-run-scheduled-effects> buildbot # [    0.398707] ... max period:                00007fffffffffff245vm-test-run-scheduled-effects> buildbot # [    0.399707] ... global_ctrl mask:          000000000000003f246vm-test-run-scheduled-effects> buildbot # [    0.400883] signal: max sigframe size: 3376247vm-test-run-scheduled-effects> buildbot # [    0.401830] rcu: Hierarchical SRCU implementation.248vm-test-run-scheduled-effects> buildbot # [    0.402712] rcu: 	Max phase no-delay instances is 400.249vm-test-run-scheduled-effects> buildbot # [    0.408389] smp: Bringing up secondary CPUs ...250vm-test-run-scheduled-effects> buildbot # [    0.409722] smp: Brought up 1 node, 1 CPU251vm-test-run-scheduled-effects> buildbot # [    0.410710] smpboot: Total of 1 processors activated (4800.01 BogoMIPS)252vm-test-run-scheduled-effects> buildbot # [    0.411904] Memory: 942616K/1048036K available (17094K kernel code, 2721K rwdata, 13512K rodata, 3644K init, 3008K bss, 98044K reserved, 0K cma-reserved)253vm-test-run-scheduled-effects> buildbot # [    0.412945] devtmpfs: initialized254vm-test-run-scheduled-effects> buildbot # [    0.413892] x86/mm: Memory block size: 128MB255vm-test-run-scheduled-effects> buildbot # [    0.415709] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns256vm-test-run-scheduled-effects> buildbot # [    0.416739] posixtimers hash table entries: 512 (order: 1, 8192 bytes, linear)257vm-test-run-scheduled-effects> buildbot # [    0.417742] futex hash table entries: 256 (16384 bytes on 1 NUMA nodes, total 16 KiB, linear).258vm-test-run-scheduled-effects> buildbot # [    0.419775] pinctrl core: initialized pinctrl subsystem259vm-test-run-scheduled-effects> buildbot # [    0.421118] PM: RTC time: 06:19:50, date: 2026-06-07260vm-test-run-scheduled-effects> buildbot # [    0.424652] NET: Registered PF_NETLINK/PF_ROUTE protocol family261vm-test-run-scheduled-effects> buildbot # [    0.426069] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations262vm-test-run-scheduled-effects> buildbot # [    0.426729] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations263vm-test-run-scheduled-effects> buildbot # [    0.427860] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations264vm-test-run-scheduled-effects> buildbot # [    0.428719] audit: initializing netlink subsys (disabled)265vm-test-run-scheduled-effects> buildbot # [    0.430038] thermal_sys: Registered thermal governor 'fair_share'266vm-test-run-scheduled-effects> buildbot # [    0.430040] thermal_sys: Registered thermal governor 'bang_bang'267vm-test-run-scheduled-effects> buildbot # [    0.430707] thermal_sys: Registered thermal governor 'step_wise'268vm-test-run-scheduled-effects> buildbot # [    0.431711] audit: type=2000 audit(1780813190.229:1): state=initialized audit_enabled=0 res=1269vm-test-run-scheduled-effects> buildbot # [    0.433710] thermal_sys: Registered thermal governor 'user_space'270vm-test-run-scheduled-effects> buildbot # [    0.433712] thermal_sys: Registered thermal governor 'power_allocator'271vm-test-run-scheduled-effects> buildbot # [    0.434727] cpuidle: using governor menu272vm-test-run-scheduled-effects> buildbot # [    0.437929] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5273vm-test-run-scheduled-effects> buildbot # [    0.439055] PCI: Using configuration type 1 for base access274vm-test-run-scheduled-effects> buildbot # [    0.439707] PCI: Using configuration type 1 for extended access275vm-test-run-scheduled-effects> buildbot # [    0.440937] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.276vm-test-run-scheduled-effects> buildbot # [    0.445847] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages277vm-test-run-scheduled-effects> buildbot # [    0.446708] HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page278vm-test-run-scheduled-effects> buildbot # [    0.451707] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages279vm-test-run-scheduled-effects> buildbot # [    0.452707] HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page280vm-test-run-scheduled-effects> buildbot # [    0.461107] ACPI: Added _OSI(Module Device)281vm-test-run-scheduled-effects> buildbot # [    0.461708] ACPI: Added _OSI(Processor Device)282vm-test-run-scheduled-effects> buildbot # [    0.466707] ACPI: Added _OSI(Processor Aggregator Device)283vm-test-run-scheduled-effects> buildbot # [    0.472564] ACPI: 1 ACPI AML tables successfully acquired and loaded284vm-test-run-scheduled-effects> buildbot # [    0.476961] ACPI: Interpreter enabled285vm-test-run-scheduled-effects> buildbot # [    0.477724] ACPI: PM: (supports S0 S3 S4 S5)286vm-test-run-scheduled-effects> buildbot # [    0.480708] ACPI: Using IOAPIC for interrupt routing287vm-test-run-scheduled-effects> buildbot # [    0.481729] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug288vm-test-run-scheduled-effects> buildbot # [    0.484706] PCI: Using E820 reservations for host bridge windows289vm-test-run-scheduled-effects> buildbot # [    0.485870] ACPI: Enabled 2 GPEs in block 00 to 0F290vm-test-run-scheduled-effects> buildbot # [    0.494852] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])291vm-test-run-scheduled-effects> buildbot # [    0.495714] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]292vm-test-run-scheduled-effects> buildbot # [    0.497167] acpiphp: Slot [3] registered293vm-test-run-scheduled-effects> buildbot # [    0.497777] acpiphp: Slot [4] registered294vm-test-run-scheduled-effects> buildbot # [    0.498759] acpiphp: Slot [5] registered295vm-test-run-scheduled-effects> buildbot # [    0.499788] acpiphp: Slot [6] registered296vm-test-run-scheduled-effects> buildbot # [    0.500760] acpiphp: Slot [7] registered297vm-test-run-scheduled-effects> buildbot # [    0.501771] acpiphp: Slot [8] registered298vm-test-run-scheduled-effects> buildbot # [    0.502752] acpiphp: Slot [9] registered299vm-test-run-scheduled-effects> buildbot # [    0.503754] acpiphp: Slot [10] registered300vm-test-run-scheduled-effects> buildbot # [    0.504758] acpiphp: Slot [11] registered301vm-test-run-scheduled-effects> buildbot # [    0.505772] acpiphp: Slot [12] registered302vm-test-run-scheduled-effects> buildbot # [    0.506751] acpiphp: Slot [13] registered303vm-test-run-scheduled-effects> buildbot # [    0.507740] acpiphp: Slot [14] registered304vm-test-run-scheduled-effects> buildbot # [    0.508739] acpiphp: Slot [15] registered305vm-test-run-scheduled-effects> buildbot # [    0.509757] acpiphp: Slot [16] registered306vm-test-run-scheduled-effects> buildbot # [    0.510740] acpiphp: Slot [17] registered307vm-test-run-scheduled-effects> buildbot # [    0.511739] acpiphp: Slot [18] registered308vm-test-run-scheduled-effects> buildbot # [    0.512760] acpiphp: Slot [19] registered309vm-test-run-scheduled-effects> buildbot # [    0.513741] acpiphp: Slot [20] registered310vm-test-run-scheduled-effects> buildbot # [    0.514739] acpiphp: Slot [21] registered311vm-test-run-scheduled-effects> buildbot # [    0.515740] acpiphp: Slot [22] registered312vm-test-run-scheduled-effects> buildbot # [    0.516756] acpiphp: Slot [23] registered313vm-test-run-scheduled-effects> buildbot # [    0.517741] acpiphp: Slot [24] registered314vm-test-run-scheduled-effects> buildbot # [    0.518740] acpiphp: Slot [25] registered315vm-test-run-scheduled-effects> buildbot # [    0.519740] acpiphp: Slot [26] registered316vm-test-run-scheduled-effects> buildbot # [    0.520757] acpiphp: Slot [27] registered317vm-test-run-scheduled-effects> buildbot # [    0.521740] acpiphp: Slot [28] registered318vm-test-run-scheduled-effects> buildbot # [    0.522740] acpiphp: Slot [29] registered319vm-test-run-scheduled-effects> buildbot # [    0.523740] acpiphp: Slot [30] registered320vm-test-run-scheduled-effects> buildbot # [    0.524762] acpiphp: Slot [31] registered321vm-test-run-scheduled-effects> buildbot # [    0.525730] PCI host bridge to bus 0000:00322vm-test-run-scheduled-effects> buildbot # [    0.526713] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]323vm-test-run-scheduled-effects> buildbot # [    0.527708] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]324vm-test-run-scheduled-effects> buildbot # [    0.528708] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]325vm-test-run-scheduled-effects> buildbot # [    0.529708] pci_bus 0000:00: root bus resource [mem 0x40000000-0xfebfffff window]326vm-test-run-scheduled-effects> buildbot # [    0.530708] pci_bus 0000:00: root bus resource [mem 0x100000000-0x17fffffff window]327vm-test-run-scheduled-effects> buildbot # [    0.531708] pci_bus 0000:00: root bus resource [bus 00-ff]328vm-test-run-scheduled-effects> buildbot # [    0.533050] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 conventional PCI endpoint329vm-test-run-scheduled-effects> buildbot # [    0.534696] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 conventional PCI endpoint330vm-test-run-scheduled-effects> buildbot # [    0.536639] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 conventional PCI endpoint331vm-test-run-scheduled-effects> buildbot # [    0.539281] pci 0000:00:01.1: BAR 4 [io  0xc1e0-0xc1ef]332vm-test-run-scheduled-effects> buildbot # [    0.539773] pci 0000:00:01.1: BAR 0 [io  0x01f0-0x01f7]: legacy IDE quirk333vm-test-run-scheduled-effects> buildbot # [    0.540708] pci 0000:00:01.1: BAR 1 [io  0x03f6]: legacy IDE quirk334vm-test-run-scheduled-effects> buildbot # [    0.541707] pci 0000:00:01.1: BAR 2 [io  0x0170-0x0177]: legacy IDE quirk335vm-test-run-scheduled-effects> buildbot # [    0.542708] pci 0000:00:01.1: BAR 3 [io  0x0376]: legacy IDE quirk336vm-test-run-scheduled-effects> buildbot # [    0.544027] pci 0000:00:01.2: [8086:7020] type 00 class 0x0c0300 conventional PCI endpoint337vm-test-run-scheduled-effects> buildbot # [    0.545774] pci 0000:00:01.2: BAR 4 [io  0xc100-0xc11f]338vm-test-run-scheduled-effects> buildbot # [    0.547987] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 conventional PCI endpoint339vm-test-run-scheduled-effects> buildbot # [    0.549421] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI340vm-test-run-scheduled-effects> buildbot # [    0.550723] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB341vm-test-run-scheduled-effects> buildbot # [    0.552122] pci 0000:00:02.0: [1234:1111] type 00 class 0x030000 conventional PCI endpoint342vm-test-run-scheduled-effects> buildbot # [    0.554798] pci 0000:00:02.0: BAR 0 [mem 0xfd000000-0xfdffffff pref]343vm-test-run-scheduled-effects> buildbot # [    0.555735] pci 0000:00:02.0: BAR 2 [mem 0xfebd0000-0xfebd0fff]344vm-test-run-scheduled-effects> buildbot # [    0.556761] pci 0000:00:02.0: ROM [mem 0xfebc0000-0xfebcffff pref]345vm-test-run-scheduled-effects> buildbot # [    0.557952] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]346vm-test-run-scheduled-effects> buildbot # [    0.559890] pci 0000:00:03.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint347vm-test-run-scheduled-effects> buildbot # [    0.562743] pci 0000:00:03.0: BAR 0 [io  0xc120-0xc13f]348vm-test-run-scheduled-effects> buildbot # [    0.563723] pci 0000:00:03.0: BAR 1 [mem 0xfebd1000-0xfebd1fff]349vm-test-run-scheduled-effects> buildbot # [    0.564761] pci 0000:00:03.0: BAR 4 [mem 0xfe000000-0xfe003fff 64bit pref]350vm-test-run-scheduled-effects> buildbot # [    0.565722] pci 0000:00:03.0: ROM [mem 0xfeb40000-0xfeb7ffff pref]351vm-test-run-scheduled-effects> buildbot # [    0.569298] pci 0000:00:04.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint352vm-test-run-scheduled-effects> buildbot # [    0.572748] pci 0000:00:04.0: BAR 0 [io  0xc140-0xc15f]353vm-test-run-scheduled-effects> buildbot # [    0.573722] pci 0000:00:04.0: BAR 1 [mem 0xfebd2000-0xfebd2fff]354vm-test-run-scheduled-effects> buildbot # [    0.574761] pci 0000:00:04.0: BAR 4 [mem 0xfe004000-0xfe007fff 64bit pref]355vm-test-run-scheduled-effects> buildbot # [    0.577746] pci 0000:00:05.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint356vm-test-run-scheduled-effects> buildbot # [    0.580746] pci 0000:00:05.0: BAR 0 [io  0xc080-0xc0bf]357vm-test-run-scheduled-effects> buildbot # [    0.581723] pci 0000:00:05.0: BAR 1 [mem 0xfebd3000-0xfebd3fff]358vm-test-run-scheduled-effects> buildbot # [    0.582773] pci 0000:00:05.0: BAR 4 [mem 0xfe008000-0xfe00bfff 64bit pref]359vm-test-run-scheduled-effects> buildbot # [    0.585811] pci 0000:00:06.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint360vm-test-run-scheduled-effects> buildbot # [    0.588722] pci 0000:00:06.0: BAR 0 [io  0xc160-0xc17f]361vm-test-run-scheduled-effects> buildbot # [    0.589722] pci 0000:00:06.0: BAR 1 [mem 0xfebd4000-0xfebd4fff]362vm-test-run-scheduled-effects> buildbot # [    0.590760] pci 0000:00:06.0: BAR 4 [mem 0xfe00c000-0xfe00ffff 64bit pref]363vm-test-run-scheduled-effects> buildbot # [    0.593721] pci 0000:00:07.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint364vm-test-run-scheduled-effects> buildbot # [    0.596614] pci 0000:00:07.0: BAR 0 [io  0xc180-0xc19f]365vm-test-run-scheduled-effects> buildbot # [    0.597777] pci 0000:00:07.0: BAR 1 [mem 0xfebd5000-0xfebd5fff]366vm-test-run-scheduled-effects> buildbot # [    0.598761] pci 0000:00:07.0: BAR 4 [mem 0xfe010000-0xfe013fff 64bit pref]367vm-test-run-scheduled-effects> buildbot # [    0.603226] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint368vm-test-run-scheduled-effects> buildbot # [    0.605746] pci 0000:00:08.0: BAR 0 [io  0xc000-0xc07f]369vm-test-run-scheduled-effects> buildbot # [    0.606722] pci 0000:00:08.0: BAR 1 [mem 0xfebd6000-0xfebd6fff]370vm-test-run-scheduled-effects> buildbot # [    0.607761] pci 0000:00:08.0: BAR 4 [mem 0xfe014000-0xfe017fff 64bit pref]371vm-test-run-scheduled-effects> buildbot # [    0.610958] pci 0000:00:09.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint372vm-test-run-scheduled-effects> buildbot # [    0.613745] pci 0000:00:09.0: BAR 0 [io  0xc1a0-0xc1bf]373vm-test-run-scheduled-effects> buildbot # [    0.614722] pci 0000:00:09.0: BAR 1 [mem 0xfebd7000-0xfebd7fff]374vm-test-run-scheduled-effects> buildbot # [    0.615761] pci 0000:00:09.0: BAR 4 [mem 0xfe018000-0xfe01bfff 64bit pref]375vm-test-run-scheduled-effects> buildbot # [    0.616722] pci 0000:00:09.0: ROM [mem 0xfeb80000-0xfebbffff pref]376vm-test-run-scheduled-effects> buildbot # [    0.619721] pci 0000:00:0a.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint377vm-test-run-scheduled-effects> buildbot # [    0.622280] pci 0000:00:0a.0: BAR 1 [mem 0xfebd8000-0xfebd8fff]378vm-test-run-scheduled-effects> buildbot # [    0.622768] pci 0000:00:0a.0: BAR 4 [mem 0xfe01c000-0xfe01ffff 64bit pref]379vm-test-run-scheduled-effects> buildbot # [    0.625721] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint380vm-test-run-scheduled-effects> buildbot # [    0.628752] pci 0000:00:0b.0: BAR 0 [io  0xc0c0-0xc0ff]381vm-test-run-scheduled-effects> buildbot # [    0.629723] pci 0000:00:0b.0: BAR 1 [mem 0xfebd9000-0xfebd9fff]382vm-test-run-scheduled-effects> buildbot # [    0.630761] pci 0000:00:0b.0: BAR 4 [mem 0xfe020000-0xfe023fff 64bit pref]383vm-test-run-scheduled-effects> buildbot # [    0.633760] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint384vm-test-run-scheduled-effects> buildbot # [    0.636549] pci 0000:00:0c.0: BAR 0 [io  0xc1c0-0xc1df]385vm-test-run-scheduled-effects> buildbot # [    0.637722] pci 0000:00:0c.0: BAR 1 [mem 0xfebda000-0xfebdafff]386vm-test-run-scheduled-effects> buildbot # [    0.638760] pci 0000:00:0c.0: BAR 4 [mem 0xfe024000-0xfe027fff 64bit pref]387vm-test-run-scheduled-effects> buildbot # [    0.647226] ACPI: PCI: Interrupt link LNKA configured for IRQ 10388vm-test-run-scheduled-effects> buildbot # [    0.647944] ACPI: PCI: Interrupt link LNKB configured for IRQ 10389vm-test-run-scheduled-effects> buildbot # [    0.648903] ACPI: PCI: Interrupt link LNKC configured for IRQ 11390vm-test-run-scheduled-effects> buildbot # [    0.649897] ACPI: PCI: Interrupt link LNKD configured for IRQ 11391vm-test-run-scheduled-effects> buildbot # [    0.650821] ACPI: PCI: Interrupt link LNKS configured for IRQ 9392vm-test-run-scheduled-effects> buildbot # [    0.652831] iommu: Default domain type: Translated393vm-test-run-scheduled-effects> buildbot # [    0.653718] iommu: DMA domain TLB invalidation policy: lazy mode394vm-test-run-scheduled-effects> buildbot # [    0.655028] ACPI: bus type USB registered395vm-test-run-scheduled-effects> buildbot # [    0.655764] usbcore: registered new interface driver usbfs396vm-test-run-scheduled-effects> buildbot # [    0.656750] usbcore: registered new interface driver hub397vm-test-run-scheduled-effects> buildbot # [    0.657726] usbcore: registered new device driver usb398vm-test-run-scheduled-effects> buildbot # [    0.659693] NetLabel: Initializing399vm-test-run-scheduled-effects> buildbot # [    0.660535] NetLabel:  domain hash size = 128400vm-test-run-scheduled-effects> buildbot # [    0.661707] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO401vm-test-run-scheduled-effects> buildbot # [    0.662748] NetLabel:  unlabeled traffic allowed by default402vm-test-run-scheduled-effects> buildbot # [    0.663724] PCI: Using ACPI for IRQ routing403vm-test-run-scheduled-effects> buildbot # [    0.665390] pci 0000:00:02.0: vgaarb: setting as boot VGA device404vm-test-run-scheduled-effects> buildbot # [    0.665702] pci 0000:00:02.0: vgaarb: bridge control possible405vm-test-run-scheduled-effects> buildbot # [    0.665702] pci 0000:00:02.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none406vm-test-run-scheduled-effects> buildbot # [    0.665709] vgaarb: loaded407vm-test-run-scheduled-effects> buildbot # [    0.666867] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0408vm-test-run-scheduled-effects> buildbot # [    0.667707] hpet0: 3 comparators, 64-bit 100.000000 MHz counter409vm-test-run-scheduled-effects> buildbot # [    0.671788] clocksource: Switched to clocksource kvm-clock410vm-test-run-scheduled-effects> buildbot # [    0.676028] VFS: Disk quotas dquot_6.6.0411vm-test-run-scheduled-effects> buildbot # [    0.677321] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)412vm-test-run-scheduled-effects> buildbot # [    0.679685] pnp: PnP ACPI init413vm-test-run-scheduled-effects> buildbot # [    0.681364] pnp: PnP ACPI: found 6 devices414vm-test-run-scheduled-effects> buildbot # [    0.689609] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns415vm-test-run-scheduled-effects> buildbot # [    0.692267] clocksource: Switched to clocksource acpi_pm416vm-test-run-scheduled-effects> buildbot # [    0.694015] NET: Registered PF_INET protocol family417vm-test-run-scheduled-effects> buildbot # [    0.695836] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)418vm-test-run-scheduled-effects> buildbot # [    0.714838] tcp_listen_portaddr_hash hash table entries: 512 (order: 1, 8192 bytes, linear)419vm-test-run-scheduled-effects> buildbot # [    0.717548] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)420vm-test-run-scheduled-effects> buildbot # [    0.719943] TCP established hash table entries: 8192 (order: 4, 65536 bytes, linear)421vm-test-run-scheduled-effects> buildbot # [    0.722333] TCP bind hash table entries: 8192 (order: 6, 262144 bytes, linear)422vm-test-run-scheduled-effects> buildbot # [    0.724600] TCP: Hash tables configured (established 8192 bind 8192)423vm-test-run-scheduled-effects> buildbot # [    0.726690] MPTCP token hash table entries: 1024 (order: 3, 24576 bytes, linear)424vm-test-run-scheduled-effects> buildbot # [    0.729016] UDP hash table entries: 512 (order: 3, 32768 bytes, linear)425vm-test-run-scheduled-effects> buildbot # [    0.731031] UDP-Lite hash table entries: 512 (order: 3, 32768 bytes, linear)426vm-test-run-scheduled-effects> buildbot # [    0.733178] NET: Registered PF_UNIX/PF_LOCAL protocol family427vm-test-run-scheduled-effects> buildbot # [    0.734975] NET: Registered PF_XDP protocol family428vm-test-run-scheduled-effects> buildbot # [    0.736558] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]429vm-test-run-scheduled-effects> buildbot # [    0.738486] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]430vm-test-run-scheduled-effects> buildbot # [    0.740425] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]431vm-test-run-scheduled-effects> buildbot # [    0.742517] pci_bus 0000:00: resource 7 [mem 0x40000000-0xfebfffff window]432vm-test-run-scheduled-effects> buildbot # [    0.744661] pci_bus 0000:00: resource 8 [mem 0x100000000-0x17fffffff window]433vm-test-run-scheduled-effects> buildbot # [    0.746868] pci 0000:00:01.0: PIIX3: Enabling Passive Release434vm-test-run-scheduled-effects> buildbot # [    0.748710] pci 0000:00:00.0: Limiting direct PCI/PCI transfers435vm-test-run-scheduled-effects> buildbot # [    0.752099] ACPI: \_SB_.LNKD: Enabled at IRQ 11436vm-test-run-scheduled-effects> buildbot # [    0.755535] PCI: CLS 0 bytes, default 64437vm-test-run-scheduled-effects> buildbot # [    0.757116] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983f10a64, max_idle_ns: 440795218721 ns438vm-test-run-scheduled-effects> buildbot # [    0.760153] Trying to unpack rootfs image as initramfs...439vm-test-run-scheduled-effects> buildbot # [    0.806930] Initialise system trusted keyrings440vm-test-run-scheduled-effects> buildbot # [    0.811841] workingset: timestamp_bits=40 max_order=18 bucket_order=0441vm-test-run-scheduled-effects> buildbot # [    0.837018] Key type asymmetric registered442vm-test-run-scheduled-effects> buildbot # [    0.838386] Asymmetric key parser 'x509' registered443vm-test-run-scheduled-effects> buildbot # [    0.842724] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)444vm-test-run-scheduled-effects> buildbot # [    0.849713] io scheduler mq-deadline registered445vm-test-run-scheduled-effects> buildbot # [    0.853676] io scheduler kyber registered446vm-test-run-scheduled-effects> buildbot # [    0.857684] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled447vm-test-run-scheduled-effects> buildbot # [    0.862043] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A448vm-test-run-scheduled-effects> buildbot # [    0.870857] Linux agpgart interface v0.103449vm-test-run-scheduled-effects> buildbot # [    0.872263] ACPI: bus type drm_connector registered450vm-test-run-scheduled-effects> buildbot # [    0.879830] usbcore: registered new interface driver usbserial_generic451vm-test-run-scheduled-effects> buildbot # [    0.881855] usbserial: USB Serial support registered for generic452vm-test-run-scheduled-effects> buildbot # [    0.885685] amd_pstate: The CPPC feature is supported but currently disabled by the BIOS.453vm-test-run-scheduled-effects> buildbot # [    0.885685] Please enable it if your BIOS has the CPPC option.454vm-test-run-scheduled-effects> buildbot # [    0.889724] amd_pstate: the _CPC object is not present in SBIOS or ACPI disabled455vm-test-run-scheduled-effects> buildbot # [    0.898798] drop_monitor: Initializing network drop monitor service456vm-test-run-scheduled-effects> buildbot # [    0.900908] NET: Registered PF_INET6 protocol family457vm-test-run-scheduled-effects> buildbot # [    0.907231] Segment Routing with IPv6458vm-test-run-scheduled-effects> buildbot # [    0.911696] In-situ OAM (IOAM) with IPv6459vm-test-run-scheduled-effects> buildbot # [    0.913404] IPI shorthand broadcast: enabled460vm-test-run-scheduled-effects> buildbot # [    0.922429] sched_clock: Marking stable (679031225, 242617088)->(1120458965, -198810652)461vm-test-run-scheduled-effects> buildbot # [    0.929875] registered taskstats version 1462vm-test-run-scheduled-effects> buildbot # [    0.931479] Loading compiled-in X.509 certificates463vm-test-run-scheduled-effects> buildbot # [    0.954482] Demotion targets for Node 0: null464vm-test-run-scheduled-effects> buildbot # [    0.957724] Key type .fscrypt registered465vm-test-run-scheduled-effects> buildbot # [    0.958997] Key type fscrypt-provisioning registered466vm-test-run-scheduled-effects> buildbot # [    0.962779] ima: No TPM chip found, activating TPM-bypass!467vm-test-run-scheduled-effects> buildbot # [    0.964493] ima: Allocated hash algorithm: sha1468vm-test-run-scheduled-effects> buildbot # [    0.970688] ima: No architecture policies found469vm-test-run-scheduled-effects> buildbot # [    0.972311] PM:   Magic number: 14:430:316470vm-test-run-scheduled-effects> buildbot # [    0.973665] tty tty41: hash matches471vm-test-run-scheduled-effects> buildbot # [    0.979536] RAS: Correctable Errors collector initialized.472vm-test-run-scheduled-effects> buildbot # [    0.989438] clk: Disabling unused clocks473vm-test-run-scheduled-effects> buildbot # [    0.994667] PM: genpd: Disabling unused power domains474vm-test-run-scheduled-effects> buildbot # [    1.122015] Freeing initrd memory: 27520K475vm-test-run-scheduled-effects> buildbot # [    1.126136] Freeing unused decrypted memory: 2028K476vm-test-run-scheduled-effects> buildbot # [    1.129797] Freeing unused kernel image (initmem) memory: 3644K477vm-test-run-scheduled-effects> buildbot # [    1.131775] Write protecting the kernel read-only data: 32768k478vm-test-run-scheduled-effects> buildbot # [    1.134758] Freeing unused kernel image (text/rodata gap) memory: 1336K479vm-test-run-scheduled-effects> buildbot # [    1.137302] Freeing unused kernel image (rodata/data gap) memory: 824K480vm-test-run-scheduled-effects> buildbot # [    1.189752] x86/mm: Checked W+X mappings: passed, no W+X pages found.481vm-test-run-scheduled-effects> buildbot # [    1.191746] Run /init as init process482vm-test-run-scheduled-effects> buildbot # [    1.203479] systemd[1]: Inserted module 'autofs4'483vm-test-run-scheduled-effects> buildbot # [    1.220306] fuse: init (API version 7.45)484vm-test-run-scheduled-effects> buildbot # [    1.227874] ACPI: \_SB_.LNKC: Enabled at IRQ 10485vm-test-run-scheduled-effects> buildbot # [    1.237471] ACPI: \_SB_.LNKA: Enabled at IRQ 10486vm-test-run-scheduled-effects> buildbot # [    1.242378] ACPI: \_SB_.LNKB: Enabled at IRQ 11487vm-test-run-scheduled-effects> buildbot # [    1.284472] systemd[1]: Successfully made /usr/ read-only.488vm-test-run-scheduled-effects> buildbot # [    1.625076] 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)489vm-test-run-scheduled-effects> buildbot # [    1.647089] systemd[1]: Detected virtualization kvm.490vm-test-run-scheduled-effects> buildbot # [    1.651137] systemd[1]: Detected architecture x86-64.491vm-test-run-scheduled-effects> buildbot # [    1.655232] systemd[1]: Running in initrd.492vm-test-run-scheduled-effects> buildbot # [    1.659460] systemd[1]: Initializing machine ID from random generator.493vm-test-run-scheduled-effects> buildbot # [    1.664884] systemd[1]: Hostname set to <buildbot>.494vm-test-run-scheduled-effects> buildbot # [    1.724722] systemd[1]: Queued start job for default target Initrd Default Target.495vm-test-run-scheduled-effects> buildbot # [    1.779979] systemd[1]: Created slice Slice /system/modprobe.496vm-test-run-scheduled-effects> buildbot # [    1.782076] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.497vm-test-run-scheduled-effects> buildbot # [    1.784668] systemd[1]: Expecting device /dev/disk/by-label/nixos...498vm-test-run-scheduled-effects> buildbot # [    1.786743] systemd[1]: Reached target Path Units.499vm-test-run-scheduled-effects> buildbot # [    1.788369] systemd[1]: Reached target Slice Units.500vm-test-run-scheduled-effects> buildbot # [    1.790045] systemd[1]: Reached target Swaps.501vm-test-run-scheduled-effects> buildbot # [    1.791597] systemd[1]: Reached target Timer Units.502vm-test-run-scheduled-effects> buildbot # [    1.793386] systemd[1]: Listening on D-Bus System Message Bus Socket.503vm-test-run-scheduled-effects> buildbot # [    1.795673] systemd[1]: Listening on Journal Socket (/dev/log).504vm-test-run-scheduled-effects> buildbot # [    1.797796] systemd[1]: Listening on Journal Sockets.505vm-test-run-scheduled-effects> buildbot # [    1.799606] systemd[1]: Listening on udev Control Socket.506vm-test-run-scheduled-effects> buildbot # [    1.801498] systemd[1]: Listening on udev Kernel Socket.507vm-test-run-scheduled-effects> buildbot # [    1.803309] systemd[1]: Reached target Socket Units.508vm-test-run-scheduled-effects> buildbot # [    1.806975] systemd[1]: Starting Create List of Static Device Nodes...509vm-test-run-scheduled-effects> buildbot # [    1.816901] systemd[1]: Starting Load Kernel Module 9pnet_virtio...510vm-test-run-scheduled-effects> buildbot # [    1.826902] systemd[1]: Starting Load Kernel Module configfs...511vm-test-run-scheduled-effects> buildbot # [    1.846182] systemd[1]: Starting Journal Service...512vm-test-run-scheduled-effects> buildbot # [    1.860403] systemd[1]: Starting Load Kernel Modules...513vm-test-run-scheduled-effects> buildbot # [    1.863434] netfs: FS-Cache loaded514vm-test-run-scheduled-effects> buildbot # [    1.871780] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki515vm-test-run-scheduled-effects> buildbot # [    1.879850] 9pnet: Installing 9P2000 support516vm-test-run-scheduled-effects> buildbot # [    1.892166] systemd[1]: Starting Coldplug All udev Devices...517vm-test-run-scheduled-effects> buildbot # [    1.896123] systemd-journald[125]: Collecting audit messages is disabled.518vm-test-run-scheduled-effects> buildbot # [    1.923795] systemd[1]: Finished Create List of Static Device Nodes.519vm-test-run-scheduled-effects> buildbot # [    1.934319] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.520vm-test-run-scheduled-effects> buildbot # [    1.951976] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.521vm-test-run-scheduled-effects> buildbot # [    1.962714] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev522vm-test-run-scheduled-effects> buildbot # [    1.992450] systemd[1]: Finished Load Kernel Module 9pnet_virtio.523vm-test-run-scheduled-effects> buildbot # [    2.003056] systemd[1]: modprobe@configfs.service: Deactivated successfully.524vm-test-run-scheduled-effects> buildbot # [    2.013212] systemd[1]: Finished Load Kernel Module configfs.525vm-test-run-scheduled-effects> buildbot # [    2.029426] systemd[1]: Finished Load Kernel Modules.526vm-test-run-scheduled-effects> buildbot # [    2.036448] systemd[1]: Kernel Configuration File System skipped, unmet condition check ConditionPathExists=/sys/kernel/config527vm-test-run-scheduled-effects> buildbot # [    2.051706] systemd[1]: Starting Apply Kernel Variables...528vm-test-run-scheduled-effects> buildbot # [    2.073083] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...529vm-test-run-scheduled-effects> buildbot # [    1.848337] systemd-modules-load[127]: Inserted module 'dm_mod'[    2.095080] systemd[1]: Started Journal Service.530vm-test-run-scheduled-effects> buildbot # 531vm-test-run-scheduled-effects> buildbot # [    1.855262] systemd-modules-load[127]: Inserted module 'virtio_balloon'532vm-test-run-scheduled-effects> buildbot # [    1.858459] systemd-modules-load[127]: Inserted module 'virtio_gpu'533vm-test-run-scheduled-effects> buildbot # [    1.871892] systemd[1]: Finished Apply Kernel Variables.534vm-test-run-scheduled-effects> buildbot # [    1.879898] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.535vm-test-run-scheduled-effects> buildbot # [    1.890130] systemd[1]: Starting Create Static Device Nodes in /dev...536vm-test-run-scheduled-effects> buildbot # [    1.914703] systemd[1]: Finished Create Static Device Nodes in /dev.537vm-test-run-scheduled-effects> buildbot # [    1.916473] systemd[1]: Reached target Preparation for Local File Systems.538vm-test-run-scheduled-effects> buildbot # [    1.918342] systemd[1]: Reached target Local File Systems.539vm-test-run-scheduled-effects> buildbot # [    1.922175] systemd[1]: Starting Create System Files and Directories...540vm-test-run-scheduled-effects> buildbot # [    1.930775] systemd[1]: Starting Rule-based Manager for Device Events and Files...541vm-test-run-scheduled-effects> buildbot # [    1.958449] systemd[1]: Finished Create System Files and Directories.542vm-test-run-scheduled-effects> buildbot # [    1.981335] systemd-udevd[161]: Using default interface naming scheme 'v260'.543vm-test-run-scheduled-effects> buildbot # [    2.018112] systemd[1]: Started Rule-based Manager for Device Events and Files.544vm-test-run-scheduled-effects> buildbot # [    2.038201] systemd[1]: Finished Coldplug All udev Devices.545vm-test-run-scheduled-effects> buildbot # [    2.041461] systemd[1]: Reached target System Initialization.546vm-test-run-scheduled-effects> buildbot # [    2.043123] systemd[1]: Reached target Basic System.547vm-test-run-scheduled-effects> buildbot # [    2.557186] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12548vm-test-run-scheduled-effects> buildbot # [    2.583848] serio: i8042 KBD port at 0x60,0x64 irq 1549vm-test-run-scheduled-effects> buildbot # [    2.601856] serio: i8042 AUX port at 0x60,0x64 irq 12550vm-test-run-scheduled-effects> buildbot # [    2.613365] SCSI subsystem initialized551vm-test-run-scheduled-effects> buildbot # [    2.615405] virtio_blk virtio5: 1/0/0 default/read/poll queues552vm-test-run-scheduled-effects> buildbot # [    2.630779] virtio_blk virtio5: [vda] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB)553vm-test-run-scheduled-effects> buildbot # [    2.656865] uhci_hcd 0000:00:01.2: UHCI Host Controller554vm-test-run-scheduled-effects> buildbot # [    2.674683] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1555vm-test-run-scheduled-effects> buildbot # [    2.688496] uhci_hcd 0000:00:01.2: detected 2 ports556vm-test-run-scheduled-effects> buildbot # [    2.697926] uhci_hcd 0000:00:01.2: irq 11, io port 0x0000c100557vm-test-run-scheduled-effects> buildbot # [    2.712787] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.18558vm-test-run-scheduled-effects> buildbot # [    2.714805] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1559vm-test-run-scheduled-effects> buildbot # [    2.483944] systemd[1]: Starting Virtual Console Setup...560vm-test-run-scheduled-effects> buildbot # [    2.497859] (udev-worker)[175]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.561vm-test-run-scheduled-effects> buildbot # [    2.501804] (udev-worker)[175]: Network interface NamePolicy= disabled on kernel command line.562vm-test-run-scheduled-effects> buildbot # [    2.507409] (udev-worker)[170]: Network interface NamePolicy= disabled on kernel command line.563vm-test-run-scheduled-effects> buildbot # [    2.762872] usb usb1: Product: UHCI Host Controller564vm-test-run-scheduled-effects> buildbot # [    2.532540] systemd-vconsole-setup[180]: Configuration of first virtual console was skipped, ignoring remaining ones.565vm-test-run-scheduled-effects> buildbot # [    2.539668] systemd[1]: Finished Virtual Console Setup.566vm-test-run-scheduled-effects> buildbot # [    2.786583] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0567vm-test-run-scheduled-effects> buildbot # [    2.791700] usb usb1: Manufacturer: Linux 6.18.33 uhci_hcd568vm-test-run-scheduled-effects> buildbot # [    2.806672] usb usb1: SerialNumber: 0000:00:01.2569vm-test-run-scheduled-effects> buildbot # [    2.575770] systemd[1]: Found device /dev/disk/by-label/nixos.570vm-test-run-scheduled-effects> buildbot # [    2.577423] systemd[1]: Reached target Initrd Root Device.571vm-test-run-scheduled-effects> buildbot # [    2.823856] hub 1-0:1.0: USB hub found572vm-test-run-scheduled-effects> buildbot # [    2.584112] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos...573vm-test-run-scheduled-effects> buildbot # [    2.833553] scsi host0: ata_piix574vm-test-run-scheduled-effects> buildbot # [    2.834559] hub 1-0:1.0: 2 ports detected575vm-test-run-scheduled-effects> buildbot # [    2.835932] scsi host1: ata_piix576vm-test-run-scheduled-effects> buildbot # [    2.844930] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc1e0 irq 14 lpm-pol 0577vm-test-run-scheduled-effects> buildbot # [    2.856506] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc1e8 irq 15 lpm-pol 0578vm-test-run-scheduled-effects> buildbot # [    2.618903] systemd-fsck[194]: nixos: clean, 12/65536 files, 13019/262144 blocks579vm-test-run-scheduled-effects> buildbot # [    2.628926] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos.580vm-test-run-scheduled-effects> buildbot # [    2.677243] systemd[1]: Mounting /sysroot...581vm-test-run-scheduled-effects> buildbot # [    3.021449] ata2: found unknown device (class 0)582vm-test-run-scheduled-effects> buildbot # [    3.027027] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100583vm-test-run-scheduled-effects> buildbot # [    3.037038] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.5+ PQ: 0 ANSI: 5584vm-test-run-scheduled-effects> buildbot # [    3.061724] usb 1-1: new full-speed USB device number 2 using uhci_hcd585vm-test-run-scheduled-effects> buildbot # [    3.108754] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray586vm-test-run-scheduled-effects> buildbot # [    3.127093] cdrom: Uniform CD-ROM driver Revision: 3.20587vm-test-run-scheduled-effects> buildbot # [    3.152944] EXT4-fs (vda): mounted filesystem c0818cc1-35ca-43f0-84eb-d807714be832 r/w with ordered data mode. Quota mode: none.588vm-test-run-scheduled-effects> buildbot # [    2.915722] systemd[1]: Mounted /sysroot.589vm-test-run-scheduled-effects> buildbot # [    2.920377] systemd[1]: Reached target Initrd Root File System.590vm-test-run-scheduled-effects> buildbot # [    2.926108] systemd[1]: Starting Mountpoints Configured in the Real Root...591vm-test-run-scheduled-effects> buildbot # [    2.940403] systemd-sysroot-fstab-check[210]: /sysroot should be mounted in the initrd, will request daemon-reload.592vm-test-run-scheduled-effects> buildbot # [    2.946099] systemd[1]: Reload requested from client PID 210 ('systemd-sysroot') (unit initrd-parse-etc.service)...593vm-test-run-scheduled-effects> buildbot # [    2.948844] systemd[1]: Reloading...594vm-test-run-scheduled-effects> buildbot # [    3.236345] usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00595vm-test-run-scheduled-effects> buildbot # [    3.238429] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=10596vm-test-run-scheduled-effects> buildbot # [    3.242762] usb 1-1: Product: QEMU USB Tablet597vm-test-run-scheduled-effects> buildbot # [    3.244673] usb 1-1: Manufacturer: QEMU598vm-test-run-scheduled-effects> buildbot # [    3.247369] usb 1-1: SerialNumber: 28754-0000:00:01.2-1599vm-test-run-scheduled-effects> buildbot # [    3.285362] hid: raw HID events driver (C) Jiri Kosina600vm-test-run-scheduled-effects> buildbot # [    3.314008] usbcore: registered new interface driver usbhid601vm-test-run-scheduled-effects> buildbot # [    3.315483] usbhid: USB HID core driver602vm-test-run-scheduled-effects> buildbot # [    3.339986] 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/input2603vm-test-run-scheduled-effects> buildbot # [    3.349797] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:01.2-1/input0604vm-test-run-scheduled-effects> buildbot # [    3.228764] systemd[1]: Reloading finished in 283 ms.605vm-test-run-scheduled-effects> buildbot # [    3.243495] systemd-sysroot-fstab-check[210]: Requesting initrd-fs.target/start/replace...606vm-test-run-scheduled-effects> buildbot # [    3.295267] systemd-sysroot-fstab-check[210]: Requesting swap.target/start/replace...607vm-test-run-scheduled-effects> buildbot # [    3.302928] systemd[1]: initrd-parse-etc.service: Deactivated successfully.608vm-test-run-scheduled-effects> buildbot # [    3.307106] systemd[1]: Finished Mountpoints Configured in the Real Root.609vm-test-run-scheduled-effects> buildbot # [    3.308985] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies.610vm-test-run-scheduled-effects> buildbot # [    3.314226] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio611vm-test-run-scheduled-effects> buildbot # [    3.683748] systemd[1]: Mounting /sysroot/nix/.ro-store...612vm-test-run-scheduled-effects> buildbot # [    3.697456] systemd[1]: Mounting /sysroot/nix/.rw-store...613vm-test-run-scheduled-effects> buildbot # [    3.712996] systemd[1]: Mounting /sysroot/run...614vm-test-run-scheduled-effects> buildbot # [    3.729359] systemd[1]: Mounting /sysroot/tmp/shared...615vm-test-run-scheduled-effects> buildbot # [    3.745553] systemd[1]: Mounting /sysroot/tmp/xchg...616vm-test-run-scheduled-effects> buildbot # [    4.000257] 9p: Installing v9fs 9p2000 file system support617vm-test-run-scheduled-effects> buildbot # [    3.770514] systemd[1]: Mounted /sysroot/nix/.ro-store.618vm-test-run-scheduled-effects> buildbot # [    3.782079] systemd[1]: Mounted /sysroot/nix/.rw-store.619vm-test-run-scheduled-effects> buildbot # [    3.785108] systemd[1]: Mounted /sysroot/run.620vm-test-run-scheduled-effects> buildbot # [    3.786433] systemd[1]: Mounted /sysroot/tmp/shared.621vm-test-run-scheduled-effects> buildbot # [    3.788241] systemd[1]: Mounted /sysroot/tmp/xchg.622vm-test-run-scheduled-effects> buildbot # [    3.795101] systemd[1]: Starting rw-sysroot-nix-store.service...623vm-test-run-scheduled-effects> buildbot # [    3.806638] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.624vm-test-run-scheduled-effects> buildbot # [    3.811113] systemd[1]: Finished rw-sysroot-nix-store.service.625vm-test-run-scheduled-effects> buildbot # [    4.682156] systemd[1]: Mounting /sysroot/nix/store...626vm-test-run-scheduled-effects> buildbot # [    4.730292] systemd[1]: Mounted /sysroot/nix/store.627vm-test-run-scheduled-effects> buildbot # [    4.731715] systemd[1]: Reached target Initrd File Systems.628vm-test-run-scheduled-effects> buildbot # [    4.735552] systemd[1]: Starting Find NixOS closure...629vm-test-run-scheduled-effects> buildbot # [    4.740908] systemd[1]: Starting Create Volatile Files and Directories in the Real Root...630vm-test-run-scheduled-effects> buildbot # [    4.764989] systemd[1]: Finished Create Volatile Files and Directories in the Real Root.631vm-test-run-scheduled-effects> buildbot # [    4.767728] systemd[1]: sysroot-run-credentials-systemd\x2dtmpfiles\x2dsetup\x2dsysroot.service.mount: Deactivated successfully.632vm-test-run-scheduled-effects> buildbot # [    4.781174] systemd[1]: Finished Find NixOS closure.633vm-test-run-scheduled-effects> buildbot # [    4.783128] systemd[1]: Reached target Initrd Default Target.634vm-test-run-scheduled-effects> buildbot # [    4.786898] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...635vm-test-run-scheduled-effects> buildbot # [    4.804431] systemd[1]: Stopped target Initrd Default Target.636vm-test-run-scheduled-effects> buildbot # [    4.806174] systemd[1]: Stopped target Basic System.637vm-test-run-scheduled-effects> buildbot # [    4.808640] systemd[1]: Stopped target Initrd Root Device.638vm-test-run-scheduled-effects> buildbot # [    4.811112] systemd[1]: Stopped target Path Units.639vm-test-run-scheduled-effects> buildbot # [    4.812464] systemd[1]: systemd-ask-password-console.path: Deactivated successfully.640vm-test-run-scheduled-effects> buildbot # [    4.814398] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.641vm-test-run-scheduled-effects> buildbot # [    4.816485] systemd[1]: Stopped target Slice Units.642vm-test-run-scheduled-effects> buildbot # [    4.818272] systemd[1]: Stopped target Socket Units.643vm-test-run-scheduled-effects> buildbot # [    4.820391] systemd[1]: Stopped target System Initialization.644vm-test-run-scheduled-effects> buildbot # [    4.822181] systemd[1]: Stopped target Swaps.645vm-test-run-scheduled-effects> buildbot # [    4.824228] systemd[1]: Stopped target Timer Units.646vm-test-run-scheduled-effects> buildbot # [    4.825596] systemd[1]: dbus.socket: Deactivated successfully.647vm-test-run-scheduled-effects> buildbot # [    4.827655] systemd[1]: Closed D-Bus System Message Bus Socket.648vm-test-run-scheduled-effects> buildbot # [    4.830230] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully.649vm-test-run-scheduled-effects> buildbot # [    4.832240] systemd[1]: Stopped Find NixOS closure.650vm-test-run-scheduled-effects> buildbot # [    4.834101] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio651vm-test-run-scheduled-effects> buildbot # [    4.838554] systemd[1]: Starting rw-sysroot-nix-store.service...652vm-test-run-scheduled-effects> buildbot # [    4.840271] systemd[1]: systemd-sysctl.service: Deactivated successfully.653vm-test-run-scheduled-effects> buildbot # [    4.843185] systemd[1]: Stopped Apply Kernel Variables.654vm-test-run-scheduled-effects> buildbot # [    4.848863] systemd[1]: systemd-modules-load.service: Deactivated successfully.655vm-test-run-scheduled-effects> buildbot # [    4.851231] systemd[1]: Stopped Load Kernel Modules.656vm-test-run-scheduled-effects> buildbot # [    4.857198] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully.657vm-test-run-scheduled-effects> buildbot # [    4.860120] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root.658vm-test-run-scheduled-effects> buildbot # [    4.864142] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.659vm-test-run-scheduled-effects> buildbot # [    4.866213] systemd[1]: Stopped Create System Files and Directories.660vm-test-run-scheduled-effects> buildbot # [    4.869853] systemd[1]: Stopped target Local File Systems.661vm-test-run-scheduled-effects> buildbot # [    4.871638] systemd[1]: Stopped target Preparation for Local File Systems.662vm-test-run-scheduled-effects> buildbot # [    4.874240] systemd[1]: systemd-udev-trigger.service: Deactivated successfully.663vm-test-run-scheduled-effects> buildbot # [    4.876160] systemd[1]: Stopped Coldplug All udev Devices.664vm-test-run-scheduled-effects> buildbot # [    4.879660] systemd[1]: Stopping Rule-based Manager for Device Events and Files...665vm-test-run-scheduled-effects> buildbot # [    4.882592] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.666vm-test-run-scheduled-effects> buildbot # [    4.884455] systemd[1]: Stopped Virtual Console Setup.667vm-test-run-scheduled-effects> buildbot # [    4.892953] systemd[1]: initrd-cleanup.service: Deactivated successfully.668vm-test-run-scheduled-effects> buildbot # [    4.896108] systemd[1]: Finished Cleaning Up and Shutting Down Daemons.669vm-test-run-scheduled-effects> buildbot # [    4.901577] systemd[1]: systemd-udevd.service: Deactivated successfully.670vm-test-run-scheduled-effects> buildbot # [    4.904894] systemd[1]: Stopped Rule-based Manager for Device Events and Files.671vm-test-run-scheduled-effects> buildbot # [    4.909584] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.672vm-test-run-scheduled-effects> buildbot # [    4.913166] systemd[1]: Finished rw-sysroot-nix-store.service.673vm-test-run-scheduled-effects> buildbot # [    4.920337] systemd[1]: systemd-udevd-control.socket: Deactivated successfully.674vm-test-run-scheduled-effects> buildbot # [    4.923218] systemd[1]: Closed udev Control Socket.675vm-test-run-scheduled-effects> buildbot # [    4.927461] systemd[1]: Starting Cleanup udev Database...676vm-test-run-scheduled-effects> buildbot # [    4.930290] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.677vm-test-run-scheduled-effects> buildbot # [    4.934086] systemd[1]: Stopped Create Static Device Nodes in /dev.678vm-test-run-scheduled-effects> buildbot # [    4.937756] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully.679vm-test-run-scheduled-effects> buildbot # [    4.941228] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully.680vm-test-run-scheduled-effects> buildbot # [    4.945610] systemd[1]: kmod-static-nodes.service: Deactivated successfully.681vm-test-run-scheduled-effects> buildbot # [    4.948293] systemd[1]: Stopped Create List of Static Device Nodes.682vm-test-run-scheduled-effects> buildbot # [    4.961395] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.683vm-test-run-scheduled-effects> buildbot # [    4.964836] systemd[1]: Finished Cleanup udev Database.684vm-test-run-scheduled-effects> buildbot # [    4.968856] systemd[1]: Reached target Switch Root.685vm-test-run-scheduled-effects> buildbot # [    4.972199] systemd[1]: Starting NixOS Activation...686vm-test-run-scheduled-effects> buildbot # [    5.133957] initrd-nixos-activation-start[504]: booting system configuration /nix/store/hp7z2p822q6306mrr7j6dc5c3m0bgp0s-nixos-system-buildbot-test687vm-test-run-scheduled-effects> buildbot # [    5.199900] initrd-nixos-activation-start[504]: running activation script...688vm-test-run-scheduled-effects> buildbot # [    5.621954] initrd-nixos-activation-start[527]: setting up /etc...689vm-test-run-scheduled-effects> buildbot # [    5.901217] systemd[1]: initrd-nixos-activation.service: Deactivated successfully.690vm-test-run-scheduled-effects> buildbot # [    5.905181] systemd[1]: Finished NixOS Activation.691vm-test-run-scheduled-effects> buildbot # [    5.909866] systemd[1]: Starting Switch Root...692vm-test-run-scheduled-effects> buildbot # [    5.923490] systemd[1]: Switching root.693vm-test-run-scheduled-effects> buildbot # [    6.309926] systemd-journald[125]: Received SIGTERM from PID 1 (systemd).694vm-test-run-scheduled-effects> buildbot # [    6.458991] NET: Registered PF_VSOCK protocol family695vm-test-run-scheduled-effects> buildbot # [    6.844972] 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)696vm-test-run-scheduled-effects> buildbot # [    6.861504] systemd[1]: Detected virtualization kvm.697vm-test-run-scheduled-effects> buildbot # [    6.864730] systemd[1]: Detected architecture x86-64.698vm-test-run-scheduled-effects> buildbot # [    6.867951] systemd[1]: Detected first boot.699vm-test-run-scheduled-effects> buildbot # [    6.876908] systemd[1]: Initializing machine ID from random generator.700vm-test-run-scheduled-effects> buildbot # [    7.134236] systemd[1]: bpf-restrict-fs: LSM BPF program attached701vm-test-run-scheduled-effects> buildbot # [    7.262899] systemd[1]: Applying preset policy.702vm-test-run-scheduled-effects> buildbot # [    7.739023] systemd[1]: Populated /etc with preset unit settings.703vm-test-run-scheduled-effects> buildbot # [    8.243518] systemd[1]: initrd-switch-root.service: Deactivated successfully.704vm-test-run-scheduled-effects> buildbot # [    8.246088] systemd[1]: Stopped initrd-switch-root.service.705vm-test-run-scheduled-effects> buildbot # [    8.249737] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.706vm-test-run-scheduled-effects> buildbot # [    8.252892] systemd[1]: Created slice Slice /system/getty.707vm-test-run-scheduled-effects> buildbot # [    8.254989] systemd[1]: Created slice User and Session Slice.708vm-test-run-scheduled-effects> buildbot # [    8.256568] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.709vm-test-run-scheduled-effects> buildbot # [    8.258722] systemd[1]: Started Forward Password Requests to Wall Directory Watch.710vm-test-run-scheduled-effects> buildbot # [    8.260840] systemd[1]: Expecting device /dev/hvc0...711vm-test-run-scheduled-effects> buildbot # [    8.262125] systemd[1]: Expecting device /dev/ttyS0...712vm-test-run-scheduled-effects> buildbot # [    8.263498] systemd[1]: Reached target Local Encrypted Volumes.713vm-test-run-scheduled-effects> buildbot # [    8.265014] systemd[1]: Stopped target initrd-fs.target.714vm-test-run-scheduled-effects> buildbot # [    8.266361] systemd[1]: Stopped target initrd-root-fs.target.715vm-test-run-scheduled-effects> buildbot # [    8.267835] systemd[1]: Stopped target initrd-switch-root.target.716vm-test-run-scheduled-effects> buildbot # [    8.269372] systemd[1]: Reached target Virtual Machines and Containers.717vm-test-run-scheduled-effects> buildbot # [    8.271035] systemd[1]: Reached target Path Units.718vm-test-run-scheduled-effects> buildbot # [    8.272299] systemd[1]: Reached target Remote File Systems.719vm-test-run-scheduled-effects> buildbot # [    8.273769] systemd[1]: Reached target Slice Units.720vm-test-run-scheduled-effects> buildbot # [    8.275058] systemd[1]: Reached target Swaps.721vm-test-run-scheduled-effects> buildbot # [    8.280387] systemd[1]: Listening on Process Core Dump Socket.722vm-test-run-scheduled-effects> buildbot # [    8.284398] systemd[1]: Listening on Credential Encryption/Decryption.723vm-test-run-scheduled-effects> buildbot # [    8.289448] systemd[1]: Starting Journal Log Access Socket...724vm-test-run-scheduled-effects> buildbot # [    8.291955] systemd[1]: Listening on Journal Audit Socket.725vm-test-run-scheduled-effects> buildbot # [    8.293906] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.726vm-test-run-scheduled-effects> buildbot # [    8.296091] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki727vm-test-run-scheduled-effects> buildbot # [    8.298666] systemd[1]: Listening on udev Control Socket.728vm-test-run-scheduled-effects> buildbot # [    8.304280] systemd[1]: Mounting Huge Pages File System...729vm-test-run-scheduled-effects> buildbot # [    8.308544] systemd[1]: Mounting POSIX Message Queue File System...730vm-test-run-scheduled-effects> buildbot # [    8.313749] systemd[1]: Mounting Kernel Debug File System...731vm-test-run-scheduled-effects> buildbot # [    8.323382] systemd[1]: Mounting Kernel Trace File System...732vm-test-run-scheduled-effects> buildbot # [    8.330992] systemd[1]: Starting Create List of Static Device Nodes...733vm-test-run-scheduled-effects> buildbot # [    8.336098] systemd[1]: Load Kernel Module 9pnet_virtio skipped, unmet condition check ConditionKernelModuleLoaded=!9pnet_virtio734vm-test-run-scheduled-effects> buildbot # [    8.348493] systemd[1]: Starting Load Kernel Module configfs...735vm-test-run-scheduled-effects> buildbot # [    8.351128] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm736vm-test-run-scheduled-effects> buildbot # [    8.353900] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore737vm-test-run-scheduled-effects> buildbot # [    8.356936] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse738vm-test-run-scheduled-effects> buildbot # [    8.366900] systemd[1]: Mounting FUSE Control File System...739vm-test-run-scheduled-effects> buildbot # [    8.369179] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67740vm-test-run-scheduled-effects> buildbot # [    8.401250] systemd[1]: Starting Journal Service...741vm-test-run-scheduled-effects> buildbot # [    8.422408] systemd[1]: Starting Load Kernel Modules...742vm-test-run-scheduled-effects> buildbot # [    8.445351] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...743vm-test-run-scheduled-effects> buildbot # [    8.454437] systemd[1]: Starting Remount Root and Kernel File Systems...744vm-test-run-scheduled-effects> buildbot # [    8.467306] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki745vm-test-run-scheduled-effects> buildbot # [    8.489893] systemd-journald[737]: Collecting audit messages is enabled.746vm-test-run-scheduled-effects> buildbot # [    8.491917] systemd[1]: Starting Coldplug All udev Devices...747vm-test-run-scheduled-effects> buildbot # [    8.518125] systemd[1]: Listening on Journal Log Access Socket.748vm-test-run-scheduled-effects> buildbot # [    8.522930] loop: module loaded749vm-test-run-scheduled-effects> buildbot # [    8.532465] systemd[1]: Mounted Huge Pages File System.750vm-test-run-scheduled-effects> buildbot # [    8.538907] systemd[1]: Started Journal Service.751vm-test-run-scheduled-effects> buildbot # [    8.299553] systemd[1]: Queued start job for default target Multi-User System.752vm-test-run-scheduled-effects> buildbot # [    8.545712] EXT4-fs (vda): re-mounted c0818cc1-35ca-43f0-84eb-d807714be832.753vm-test-run-scheduled-effects> buildbot # [    8.308391] systemd[1]: systemd-journald.service: Deactivated successfully.754vm-test-run-scheduled-effects> buildbot # [    8.310973] systemd-modules-load[738]: Inserted module 'loop'755vm-test-run-scheduled-effects> buildbot # [    8.317669] systemd[1]: Mounted POSIX Message Queue File System.756vm-test-run-scheduled-effects> buildbot # [    8.326113] systemd[1]: Mounted Kernel Debug File System.757vm-test-run-scheduled-effects> buildbot # [    8.328361] systemd[1]: Mounted Kernel Trace File System.758vm-test-run-scheduled-effects> buildbot # [    8.332247] systemd[1]: Finished Create List of Static Device Nodes.759vm-test-run-scheduled-effects> buildbot # [    8.335920] systemd[1]: modprobe@configfs.service: Deactivated successfully.760vm-test-run-scheduled-effects> buildbot # [    8.341514] systemd[1]: Finished Load Kernel Module configfs.761vm-test-run-scheduled-effects> buildbot # [    8.346357] systemd[1]: Mounted FUSE Control File System.762vm-test-run-scheduled-effects> buildbot # [    8.350710] systemd-modules-load[738]: Inserted module 'tls'763vm-test-run-scheduled-effects> buildbot # [    8.352543] systemd[1]: Finished Remount Root and Kernel File Systems.764vm-test-run-scheduled-effects> buildbot # [    8.360138] systemd[1]: Finished Load Kernel Modules.765vm-test-run-scheduled-effects> buildbot # [    8.381804] systemd[1]: Mounting Kernel Configuration File System...766vm-test-run-scheduled-effects> buildbot # [    8.387209] systemd[1]: Starting Flush Journal to Persistent Storage...767vm-test-run-scheduled-effects> buildbot # [    8.389157] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore768vm-test-run-scheduled-effects> buildbot # [    8.397102] systemd[1]: Starting Load/Save OS Random Seed...769vm-test-run-scheduled-effects> buildbot # [    8.404929] systemd-oomd[740]: No swap; memory pressure usage will be degraded770vm-test-run-scheduled-effects> buildbot # [    8.414182] systemd[1]: Starting Apply Kernel Variables...771vm-test-run-scheduled-effects> buildbot # [    8.427986] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...772vm-test-run-scheduled-effects> buildbot # [    8.430247] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki773vm-test-run-scheduled-effects> buildbot # [    8.436306] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.774vm-test-run-scheduled-effects> buildbot # [    8.744850] systemd-journald[737]: Received client request to flush runtime journal.775vm-test-run-scheduled-effects> buildbot # [    8.655742] systemd[1]: Mounted Kernel Configuration File System.776vm-test-run-scheduled-effects> buildbot # [    8.659921] systemd[1]: Finished Load/Save OS Random Seed.777vm-test-run-scheduled-effects> buildbot # [    8.664569] systemd[1]: Reached target First Boot Complete.778vm-test-run-scheduled-effects> buildbot # [    8.667251] systemd[1]: Finished Apply Kernel Variables.779vm-test-run-scheduled-effects> buildbot # [    8.669441] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.780vm-test-run-scheduled-effects> buildbot # [    8.672128] systemd[1]: Starting Create Static Device Nodes in /dev...781vm-test-run-scheduled-effects> buildbot # [    8.674524] systemd[1]: Finished Flush Journal to Persistent Storage.782vm-test-run-scheduled-effects> buildbot # [    8.725173] systemd[1]: Finished Create Static Device Nodes in /dev.783vm-test-run-scheduled-effects> buildbot # [    8.726976] systemd[1]: Reached target Preparation for Local File Systems.784vm-test-run-scheduled-effects> buildbot # [    8.733258] systemd[1]: Starting Rule-based Manager for Device Events and Files...785vm-test-run-scheduled-effects> buildbot # [    8.757231] systemd[1]: Finished Coldplug All udev Devices.786vm-test-run-scheduled-effects> buildbot # [    8.817973] systemd-udevd[769]: Using default interface naming scheme 'v260'.787vm-test-run-scheduled-effects> buildbot # [    8.937583] systemd[1]: Started Rule-based Manager for Device Events and Files.788vm-test-run-scheduled-effects> buildbot # [    9.007116] systemd[1]: Mounting /run/wrappers...789vm-test-run-scheduled-effects> buildbot # [    9.048426] systemd[1]: Mounted /run/wrappers.790vm-test-run-scheduled-effects> buildbot # [    9.050981] systemd[1]: Reached target Local File Systems.791vm-test-run-scheduled-effects> buildbot # [    9.056106] systemd[1]: Listening on Boot Loader Control Service Socket.792vm-test-run-scheduled-effects> buildbot # [    9.061440] systemd[1]: Starting register-nix-paths.service...793vm-test-run-scheduled-effects> buildbot # [    9.068513] systemd[1]: Starting Create SUID/SGID Wrappers...794vm-test-run-scheduled-effects> buildbot # [    9.070193] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.795vm-test-run-scheduled-effects> buildbot # [    9.078647] systemd[1]: Starting Save Transient machine-id to Disk...796vm-test-run-scheduled-effects> buildbot # [    9.091118] systemd[1]: Starting Create System Files and Directories...797vm-test-run-scheduled-effects> buildbot # [    9.170681] systemd[1]: Load Kernel Module fuse skipped, unmet condition check ConditionKernelModuleLoaded=!fuse798vm-test-run-scheduled-effects> buildbot # [    9.188329] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.799vm-test-run-scheduled-effects> buildbot # [    9.196496] systemd[1]: Finished Save Transient machine-id to Disk.800vm-test-run-scheduled-effects> buildbot # [    9.262672] systemd[1]: Finished Create System Files and Directories.801vm-test-run-scheduled-effects> buildbot # [    9.274891] systemd[1]: Starting Rebuild Journal Catalog...802vm-test-run-scheduled-effects> buildbot # [    9.281530] systemd[1]: Starting Record System Boot/Shutdown in UTMP...803vm-test-run-scheduled-effects> buildbot # [    9.364266] systemd[1]: Finished Record System Boot/Shutdown in UTMP.804vm-test-run-scheduled-effects> buildbot # [    9.413304] systemd[1]: Finished Rebuild Journal Catalog.805vm-test-run-scheduled-effects> buildbot # [    9.422227] systemd[1]: Starting Update is Completed...806vm-test-run-scheduled-effects> buildbot # [    9.453643] systemd[1]: Condition check resulted in /dev/hvc0 being skipped.807vm-test-run-scheduled-effects> buildbot # [    9.481951] systemd[1]: Finished Update is Completed.808vm-test-run-scheduled-effects> buildbot # [    9.514260] systemd[1]: Condition check resulted in /dev/ttyS0 being skipped.809vm-test-run-scheduled-effects> buildbot # [    9.554556] (udev-worker)[773]: Network interface NamePolicy= disabled on kernel command line.810vm-test-run-scheduled-effects> buildbot # [    9.566335] (udev-worker)[775]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.811vm-test-run-scheduled-effects> buildbot # [    9.571286] (udev-worker)[775]: Network interface NamePolicy= disabled on kernel command line.812vm-test-run-scheduled-effects> buildbot # [    9.774264] systemd[1]: Condition check resulted in Virtio network device being skipped.813vm-test-run-scheduled-effects> buildbot # [    9.777639] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore814vm-test-run-scheduled-effects> buildbot # [    9.780332] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.815vm-test-run-scheduled-effects> buildbot # [    9.784452] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67816vm-test-run-scheduled-effects> buildbot # [    9.789277] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore817vm-test-run-scheduled-effects> buildbot # [    9.792928] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki818vm-test-run-scheduled-effects> buildbot # [    9.795934] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki819vm-test-run-scheduled-effects> buildbot # [    9.805771] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.820vm-test-run-scheduled-effects> buildbot # [    9.810106] systemd[1]: Finished Create SUID/SGID Wrappers.821vm-test-run-scheduled-effects> buildbot # [   10.258051] mousedev: PS/2 mouse device common for all mice822vm-test-run-scheduled-effects> buildbot # [   10.265787] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3823vm-test-run-scheduled-effects> buildbot # [   10.298124] rtc_cmos 00:05: RTC can wake from S4824vm-test-run-scheduled-effects> buildbot # [   10.303911] ACPI: button: Power Button [PWRF]825vm-test-run-scheduled-effects> buildbot # [   10.064579] systemd[1]: Finished register-nix-paths.service.826vm-test-run-scheduled-effects> buildbot # [   10.067095] systemd[1]: Reached target System Initialization.827vm-test-run-scheduled-effects> buildbot # [   10.070928] systemd[1]: Started Discard unused filesystem blocks once a week.828vm-test-run-scheduled-effects> buildbot # [   10.072833] systemd[1]: Started Daily Cleanup of Temporary Directories.829vm-test-run-scheduled-effects> buildbot # [   10.075247] systemd[1]: Reached target Timer Units.830vm-test-run-scheduled-effects> buildbot # [   10.077484] systemd[1]: Listening on D-Bus System Message Bus Socket.831vm-test-run-scheduled-effects> buildbot # [   10.079737] systemd[1]: Listening on Nix Daemon Socket.832vm-test-run-scheduled-effects> buildbot # [   10.084164] systemd[1]: Listening on OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local).833vm-test-run-scheduled-effects> buildbot # [   10.087251] systemd[1]: Listening on Hostname Service Socket.834vm-test-run-scheduled-effects> buildbot # [   10.332467] parport_pc 00:03: reported by Plug and Play ACPI835vm-test-run-scheduled-effects> buildbot # [   10.091557] systemd[1]: Reached target Socket Units.836vm-test-run-scheduled-effects> buildbot # [   10.093053] systemd[1]: Reached target Basic System.837vm-test-run-scheduled-effects> buildbot # [   10.098579] systemd[1]: Started backdoor.service.838vm-test-run-scheduled-effects> buildbot # [   10.103111] systemd[1]: Starting Import lastlog data into lastlog2 database...839vm-test-run-scheduled-effects> buildbot # [   10.349088] Floppy drive(s): fd0 is 2.88M AMI BIOS840vm-test-run-scheduled-effects> buildbot # [   10.111454] systemd[1]: Starting Name Service Cache Daemon (nsncd)...841vm-test-run-scheduled-effects> buildbot # [   10.365558] rtc_cmos 00:05: registered as rtc0842vm-test-run-scheduled-effects> buildbot # [   10.126903] systemd[1]: Starting Post-Boot Actions...843vm-test-run-scheduled-effects> buildbot # [   10.138237] systemd[1]: Started Reset console on configuration changes.844vm-test-run-scheduled-effects> buildbot # [   10.382937] rtc_cmos 00:05: setting system clock to 2026-06-07T06:20:00 UTC (1780813200)845vm-test-run-scheduled-effects> buildbot # [   10.392275] parport0: PC-style at 0x378, irq 7 [PCSPP(,...)]846vm-test-run-scheduled-effects> buildbot # [   10.154929] systemd[1]: Starting resolvconf update...847vm-test-run-scheduled-effects> buildbot # [   10.159766] systemd[1]: SSH Host Keys Generation skipped, no trigger condition checks were met.848vm-test-run-scheduled-effects> buildbot # [   10.430500] FDC 0 is a S82078B849vm-test-run-scheduled-effects> buildbot # [   10.221181] systemd[1]: Starting D-Bus System Message Bus...850vm-test-run-scheduled-effects> buildbot # [   10.476192] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs851vm-test-run-scheduled-effects> buildbot # [   10.238646] systemd[1]: Finished Post-Boot Actions.852vm-test-run-scheduled-effects> buildbot # connecting to host...853vm-test-run-scheduled-effects> buildbot # [   10.258865] nsncd[871]: Jun 07 06:20:00.616 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"854vm-test-run-scheduled-effects> buildbot # [   10.270173] systemd[1]: Started Name Service Cache Daemon (nsncd).855vm-test-run-scheduled-effects> buildbot # [   10.295552] systemd[1]: Reached target Host and Network Name Lookups.856vm-test-run-scheduled-effects> buildbot: Guest shell says: b'Spawning backdoor root shell...\n'857vm-test-run-scheduled-effects> buildbot: connected to guest root shell858vm-test-run-scheduled-effects> buildbot: (connecting took 11.31 seconds)859vm-test-run-scheduled-effects> buildbot: (finished: waiting for the VM to finish booting, in 11.63 seconds)860vm-test-run-scheduled-effects> buildbot # [   10.298384] systemd[1]: Reached target User and Group Name Lookups.861vm-test-run-scheduled-effects> buildbot # [   10.318323] systemd[1]: Starting User Login Management...862vm-test-run-scheduled-effects> buildbot # [   10.345908] systemd[1]: Finished Import lastlog data into lastlog2 database.863vm-test-run-scheduled-effects> buildbot # [   10.640546] bochs-drm 0000:00:02.0: vgaarb: deactivate vga console864vm-test-run-scheduled-effects> buildbot # [   10.462338] dbus-broker-launch[878]: Looking up NSS user entry for 'systemd-timesync'...865vm-test-run-scheduled-effects> buildbot # [   10.709377] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0866vm-test-run-scheduled-effects> buildbot # [   10.489585] dbus-broker-launch[878]: NSS returned no entry for 'systemd-timesync'867vm-test-run-scheduled-effects> buildbot # [   10.497123] dbus-broker-launch[878]: Invalid user-name in /nix/store/vp3s96gk6l0a5q3q4y8izv0rmlfdans6-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"868vm-test-run-scheduled-effects> buildbot # [   10.505296] systemd[1]: Stopped target Host and Network Name Lookups.869vm-test-run-scheduled-effects> buildbot # [   10.507130] systemd[1]: Stopping Host and Network Name Lookups...870vm-test-run-scheduled-effects> buildbot # [   10.508711] systemd[1]: Stopped target User and Group Name Lookups.871vm-test-run-scheduled-effects> buildbot # [   10.512446] systemd[1]: Stopping User and Group Name Lookups...872vm-test-run-scheduled-effects> buildbot # [   10.516418] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...873vm-test-run-scheduled-effects> buildbot # [   10.521278] systemd[1]: nscd.service: Deactivated successfully.874vm-test-run-scheduled-effects> buildbot # [   10.807433] i2c i2c-0: Memory type 0x07 not supported yet, not instantiating SPD875vm-test-run-scheduled-effects> buildbot # [   10.823095] input: QEMU Virtio Keyboard as /devices/pci0000:00/0000:00:0a.0/virtio7/input/input4876vm-test-run-scheduled-effects> buildbot # [   10.881298] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input6877vm-test-run-scheduled-effects> buildbot # [   10.881923] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input5878vm-test-run-scheduled-effects> buildbot # [   10.937419] Console: switching to colour dummy device 80x25879vm-test-run-scheduled-effects> buildbot # [   11.069821] [drm] Found bochs VGA, ID 0xb0c5.880vm-test-run-scheduled-effects> buildbot # [   11.069823] [drm] Framebuffer size 16384 kB @ 0xfd000000, mmio @ 0xfebd0000.881vm-test-run-scheduled-effects> buildbot # [   11.075452] bochs-drm 0000:00:02.0: [drm] Registered 1 planes with drm panic882vm-test-run-scheduled-effects> buildbot # [   11.075458] [drm] Initialized bochs-drm 1.0.0 for 0000:00:02.0 on minor 0883vm-test-run-scheduled-effects> buildbot # [   10.524851] systemd[1]: Stopped Name Service Cache Daemon (nsncd).884vm-test-run-scheduled-effects> buildbot # [   10.843664] systemd[1]: Starting Name Service Cache Daemon (nsncd)...885vm-test-run-scheduled-effects> buildbot # [   10.848343] systemd[1]: Started D-Bus System Message Bus.886vm-test-run-scheduled-effects> buildbot # [   10.854416] dbus-broker-launch[878]: Ready887vm-test-run-scheduled-effects> buildbot # [   10.857365] systemd[1]: Finished resolvconf update.888vm-test-run-scheduled-effects> buildbot # [   10.863862] systemd[1]: Reached target Preparation for Network.889vm-test-run-scheduled-effects> buildbot # [   10.871924] systemd[1]: Starting DHCP Client...890vm-test-run-scheduled-effects> buildbot # [   10.874570] dhcpcd[968]: dhcpcd-10.3.1 starting891vm-test-run-scheduled-effects> buildbot # [   10.883931] systemd[1]: Starting Address configuration of eth1...892vm-test-run-scheduled-effects> buildbot # [   10.889573] systemd[1]: Starting Extra networking commands....893vm-test-run-scheduled-effects> buildbot # [   10.895779] systemd[1]: Starting Virtual Console Setup...894vm-test-run-scheduled-effects> buildbot # [   10.903223] dhcpcd[975]: dev: loaded udev895vm-test-run-scheduled-effects> buildbot # [   10.910974] systemd-logind[896]: New seat seat0.896vm-test-run-scheduled-effects> buildbot # [   10.914637] systemd-logind[896]: Watching system buttons on /dev/input/event0 (AT Translated Set 2 keyboard)897vm-test-run-scheduled-effects> buildbot # [   10.919198] systemd[1]: Started User Login Management.898vm-test-run-scheduled-effects> buildbot # [   10.920955] systemd-logind[896]: Watching system buttons on /dev/input/event2 (Power Button)899vm-test-run-scheduled-effects> buildbot # [   10.927496] systemd[1]: Starting linger-users.service...900vm-test-run-scheduled-effects> buildbot # [   11.198124] 8021q: 802.1Q VLAN Support v1.8901vm-test-run-scheduled-effects> buildbot # [   10.961140] systemd[1]: Started Name Service Cache Daemon (nsncd).902vm-test-run-scheduled-effects> buildbot # [   10.963077] nsncd[950]: Jun 07 06:20:01.318 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"903vm-test-run-scheduled-effects> buildbot # [   10.966609] systemd[1]: Reached target Host and Network Name Lookups.904vm-test-run-scheduled-effects> buildbot # [   10.973160] systemd[1]: Reached target User and Group Name Lookups.905vm-test-run-scheduled-effects> buildbot # [   11.260363] 8021q: adding VLAN 0 to HW filter on device eth1906vm-test-run-scheduled-effects> buildbot # [   11.020486] systemd[1]: linger-users.service: Deactivated successfully.907vm-test-run-scheduled-effects> buildbot # [   11.026268] systemd[1]: Finished linger-users.service.908vm-test-run-scheduled-effects> buildbot # [   11.051613] network-addresses-eth1-start[963]: adding address 192.168.1.1/24... done909vm-test-run-scheduled-effects> buildbot # [   11.080110] network-addresses-eth1-start[963]: adding address 2001:db8:1::1/64... done910vm-test-run-scheduled-effects> buildbot # [   11.112151] systemd[1]: Finished Address configuration of eth1.911vm-test-run-scheduled-effects> buildbot # [   11.199630] systemd[1]: Finished Extra networking commands..912vm-test-run-scheduled-effects> buildbot # [   11.208121] systemd[1]: Reached target Network.913vm-test-run-scheduled-effects> buildbot # [   11.272648] fbcon: bochs-drmdrmfb (fb0) is primary device914vm-test-run-scheduled-effects> buildbot # [   11.231047] systemd[1]: Starting Nginx Web Server...915vm-test-run-scheduled-effects> buildbot # [   11.235781] systemd[1]: Starting PostgreSQL Server...916vm-test-run-scheduled-effects> buildbot # [   11.244252] systemd[1]: Starting SSH Daemon...917vm-test-run-scheduled-effects> buildbot # [   11.267284] systemd[1]: Starting Permit User Sessions...918vm-test-run-scheduled-effects> buildbot # [   11.377024] ppdev: user-space parallel port driver919vm-test-run-scheduled-effects> buildbot # [   11.447105] Console: switching to colour frame buffer device 160x50920vm-test-run-scheduled-effects> buildbot # [   11.481177] cfg80211: Loading compiled-in X.509 certificates for regulatory database921vm-test-run-scheduled-effects> buildbot # [   11.520933] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'922vm-test-run-scheduled-effects> buildbot # [   11.521046] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'923vm-test-run-scheduled-effects> buildbot # [   11.523332] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2924vm-test-run-scheduled-effects> buildbot # [   11.523343] cfg80211: failed to load regulatory.db925vm-test-run-scheduled-effects> buildbot # [   11.644859] 8021q: adding VLAN 0 to HW filter on device eth0926vm-test-run-scheduled-effects> buildbot # [   11.717794] bochs-drm 0000:00:02.0: [drm] fb0: bochs-drmdrmfb frame buffer device927vm-test-run-scheduled-effects> buildbot # [   11.377895] systemd-logind[896]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)928vm-test-run-scheduled-effects> buildbot # [   11.483889] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.929vm-test-run-scheduled-effects> buildbot # [   11.489098] dhcpcd[975]: eth0: waiting for carrier930vm-test-run-scheduled-effects> buildbot # [   11.492870] dhcpcd[975]: eth0: carrier acquired931vm-test-run-scheduled-effects> buildbot # [   11.496644] dhcpcd[975]: DUID 00:01:00:01:31:b7:ca:11:52:54:00:12:34:56932vm-test-run-scheduled-effects> buildbot # [   11.499740] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.933vm-test-run-scheduled-effects> buildbot # [   11.504759] dhcpcd[975]: eth0: IAID 00:12:34:56934vm-test-run-scheduled-effects> buildbot # [   11.508482] systemd[1]: Stopped Virtual Console Setup.935vm-test-run-scheduled-effects> buildbot # [   11.514967] dhcpcd[975]: eth0: adding address fe80::5054:ff:fe12:3456936vm-test-run-scheduled-effects> buildbot # [   11.544575] systemd[1]: Starting Virtual Console Setup...937vm-test-run-scheduled-effects> buildbot # [   11.557611] systemd[1]: Finished Permit User Sessions.938vm-test-run-scheduled-effects> buildbot # [   11.585521] systemd[1]: Started Getty on tty1.939vm-test-run-scheduled-effects> buildbot # [   11.593128] systemd[1]: Reached target Login Prompts.940vm-test-run-scheduled-effects> buildbot # [   11.611209] sshd[1045]: Server listening on 0.0.0.0 port 22.941vm-test-run-scheduled-effects> buildbot # [   11.614334] sshd[1045]: Server listening on :: port 22.942vm-test-run-scheduled-effects> buildbot # [   11.620518] systemd[1]: Started SSH Daemon.943vm-test-run-scheduled-effects> buildbot # [   11.642386] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.944vm-test-run-scheduled-effects> buildbot # [   11.649304] systemd[1]: Stopped Virtual Console Setup.945vm-test-run-scheduled-effects> buildbot # [   11.686753] systemd[1]: Starting Setup git test repository with scheduled effects...946vm-test-run-scheduled-effects> buildbot # [   11.692707] systemd[1]: Starting Virtual Console Setup...947vm-test-run-scheduled-effects> buildbot # [   11.709327] nginx-pre-start[1063]: nginx: the configuration file /nix/store/gvan9sgigdp6jpl4ji3affkjql9i6v24-nginx.conf syntax is ok948vm-test-run-scheduled-effects> buildbot # [   11.713389] nginx-pre-start[1063]: nginx: configuration file /nix/store/gvan9sgigdp6jpl4ji3affkjql9i6v24-nginx.conf test is successful949vm-test-run-scheduled-effects> buildbot # [   11.735478] systemd[1]: Started Nginx Web Server.950vm-test-run-scheduled-effects> buildbot # [   11.738901] postgresql-pre-start[1066]: The files belonging to this database system will be owned by user "postgres".951vm-test-run-scheduled-effects> buildbot # [   11.742987] postgresql-pre-start[1066]: This user must also own the server process.952vm-test-run-scheduled-effects> buildbot # [   11.761324] postgresql-pre-start[1066]: The database cluster will be initialized with locale "en_US.UTF-8".953vm-test-run-scheduled-effects> buildbot # [   11.764304] postgresql-pre-start[1066]: The default database encoding has accordingly been set to "UTF8".954vm-test-run-scheduled-effects> buildbot # [   11.768274] postgresql-pre-start[1066]: The default text search configuration will be set to "english".955vm-test-run-scheduled-effects> buildbot # [   11.770784] postgresql-pre-start[1066]: Data page checksums are disabled.956vm-test-run-scheduled-effects> buildbot # [   11.774282] postgresql-pre-start[1066]: fixing permissions on existing directory /var/lib/postgresql/17 ... ok957vm-test-run-scheduled-effects> buildbot # [   11.778191] postgresql-pre-start[1066]: creating subdirectories ... ok958vm-test-run-scheduled-effects> buildbot # [   11.780686] postgresql-pre-start[1066]: selecting dynamic shared memory implementation ... posix959vm-test-run-scheduled-effects> buildbot # [   12.039301] kvm_amd: TSC scaling supported960vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit sshd.service, in 13.13 seconds)961vm-test-run-scheduled-effects> buildbot # [   12.049026] kvm_amd: Nested Virtualization enabled962vm-test-run-scheduled-effects> buildbot: waiting for unit setup-git-repo.service963vm-test-run-scheduled-effects> buildbot # [   12.055281] kvm_amd: Nested Paging enabled964vm-test-run-scheduled-effects> buildbot # [   12.058005] kvm_amd: LBR virtualization supported965vm-test-run-scheduled-effects> buildbot # [   12.059977] kvm_amd: Virtual VMLOAD VMSAVE supported966vm-test-run-scheduled-effects> buildbot # [   12.062095] kvm_amd: Virtual GIF supported967vm-test-run-scheduled-effects> buildbot # [   12.063679] kvm_amd: Virtual NMI enabled968vm-test-run-scheduled-effects> buildbot # [   11.920686] setup-git-repo-start[1091]: hint: Using 'master' as the name for the initial branch. This default branch name969vm-test-run-scheduled-effects> buildbot # [   11.923553] setup-git-repo-start[1091]: hint: will change to "main" in Git 3.0. To configure the initial branch name970vm-test-run-scheduled-effects> buildbot # [   11.927243] setup-git-repo-start[1091]: hint: to use in all of your new repositories, which will suppress this warning,971vm-test-run-scheduled-effects> buildbot # [   11.930908] setup-git-repo-start[1091]: hint: call:972vm-test-run-scheduled-effects> buildbot # [   11.933167] setup-git-repo-start[1091]: hint:973vm-test-run-scheduled-effects> buildbot # [   11.934826] setup-git-repo-start[1091]: hint: 	git config --global init.defaultBranch <name>974vm-test-run-scheduled-effects> buildbot # [   11.940475] setup-git-repo-start[1091]: hint:975vm-test-run-scheduled-effects> buildbot # [   11.943404] setup-git-repo-start[1091]: hint: Names commonly chosen instead of 'master' are 'main', 'trunk' and976vm-test-run-scheduled-effects> buildbot # [   11.946561] setup-git-repo-start[1091]: hint: 'development'. The just-created branch can be renamed via this command:977vm-test-run-scheduled-effects> buildbot # [   11.950318] setup-git-repo-start[1091]: hint:978vm-test-run-scheduled-effects> buildbot # [   11.952552] setup-git-repo-start[1091]: hint: 	git branch -m <name>979vm-test-run-scheduled-effects> buildbot # [   11.957138] setup-git-repo-start[1091]: hint:980vm-test-run-scheduled-effects> buildbot # [   11.958812] setup-git-repo-start[1091]: hint: Disable this message with "git config set advice.defaultBranchName false"981vm-test-run-scheduled-effects> buildbot # [   11.964748] setup-git-repo-start[1091]: Initialized empty Git repository in /srv/repos/test-flake.git/982vm-test-run-scheduled-effects> buildbot # [   12.218336] EDAC MC: Ver: 3.0.0983vm-test-run-scheduled-effects> buildbot # [   11.993544] postgresql-pre-start[1066]: selecting default "max_connections" ... 100984vm-test-run-scheduled-effects> buildbot # [   12.047761] setup-git-repo-start[1098]: hint: Using 'master' as the name for the initial branch. This default branch name985vm-test-run-scheduled-effects> buildbot # [   12.051158] setup-git-repo-start[1098]: hint: will change to "main" in Git 3.0. To configure the initial branch name986vm-test-run-scheduled-effects> buildbot # [   12.054509] setup-git-repo-start[1098]: hint: to use in all of your new repositories, which will suppress this warning,987vm-test-run-scheduled-effects> buildbot # [   12.057838] setup-git-repo-start[1098]: hint: call:988vm-test-run-scheduled-effects> buildbot # [   12.060178] setup-git-repo-start[1098]: hint:989vm-test-run-scheduled-effects> buildbot # [   12.062322] setup-git-repo-start[1098]: hint: 	git config --global init.defaultBranch <name>990vm-test-run-scheduled-effects> buildbot # [   12.065337] setup-git-repo-start[1098]: hint:991vm-test-run-scheduled-effects> buildbot # [   12.068258] setup-git-repo-start[1098]: hint: Names commonly chosen instead of 'master' are 'main', 'trunk' and992vm-test-run-scheduled-effects> buildbot # [   12.071217] setup-git-repo-start[1098]: hint: 'development'. The just-created branch can be renamed via this command:993vm-test-run-scheduled-effects> buildbot # [   12.073740] setup-git-repo-start[1098]: hint:994vm-test-run-scheduled-effects> buildbot # [   12.075270] setup-git-repo-start[1098]: hint: 	git branch -m <name>995vm-test-run-scheduled-effects> buildbot # [   12.077370] setup-git-repo-start[1098]: hint:996vm-test-run-scheduled-effects> buildbot # [   12.079410] setup-git-repo-start[1098]: hint: Disable this message with "git config set advice.defaultBranchName false"997vm-test-run-scheduled-effects> buildbot # [   12.082775] setup-git-repo-start[1098]: Initialized empty Git repository in /tmp/test-flake/.git/998vm-test-run-scheduled-effects> buildbot # [   12.126473] postgresql-pre-start[1066]: selecting default "shared_buffers" ... 128MB999vm-test-run-scheduled-effects> buildbot # [   12.175649] setup-git-repo-start[1111]: [master (root-commit) 9dba588] Initial commit with scheduled effects1000vm-test-run-scheduled-effects> buildbot # [   12.177995] setup-git-repo-start[1111]:  3 files changed, 131 insertions(+)1001vm-test-run-scheduled-effects> buildbot # [   12.180772] setup-git-repo-start[1111]:  create mode 100644 effects-lib.nix1002vm-test-run-scheduled-effects> buildbot # [   12.183294] setup-git-repo-start[1111]:  create mode 100644 flake.lock1003vm-test-run-scheduled-effects> buildbot # [   12.185406] setup-git-repo-start[1111]:  create mode 100644 flake.nix1004vm-test-run-scheduled-effects> buildbot # [   12.270687] setup-git-repo-start[1115]: To /srv/repos/test-flake.git1005vm-test-run-scheduled-effects> buildbot # [   12.273397] setup-git-repo-start[1115]:  * [new branch]      master -> master1006vm-test-run-scheduled-effects> buildbot # [   12.277648] setup-git-repo-start[1115]: branch 'master' set up to track 'origin/master'.1007vm-test-run-scheduled-effects> buildbot # [   12.284786] systemd[1]: Finished Setup git test repository with scheduled effects.1008vm-test-run-scheduled-effects> buildbot # [   12.320345] systemd-vconsole-setup[1077]: Configuration of first virtual console was skipped, ignoring remaining ones.1009vm-test-run-scheduled-effects> buildbot # [   12.328321] systemd[1]: Finished Virtual Console Setup.1010vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit setup-git-repo.service, in 1.22 seconds)1011vm-test-run-scheduled-effects> buildbot: waiting for unit multi-user.target1012vm-test-run-scheduled-effects> buildbot # [   13.037675] dhcpcd[975]: eth0: soliciting a DHCP lease1013vm-test-run-scheduled-effects> buildbot # [   13.300868] NET: Registered PF_PACKET protocol family1014vm-test-run-scheduled-effects> buildbot # [   13.065638] dhcpcd[975]: eth0: offered 10.0.2.15 from 10.0.2.21015vm-test-run-scheduled-effects> buildbot # [   13.068286] dhcpcd[975]: eth0: probing address 10.0.2.15/241016vm-test-run-scheduled-effects> buildbot # [   14.063717] dhcpcd[975]: eth0: soliciting an IPv6 router1017vm-test-run-scheduled-effects> buildbot # [   14.065894] dhcpcd[975]: eth0: Router Advertisement from fe80::21018vm-test-run-scheduled-effects> buildbot # [   14.067576] dhcpcd[975]: eth0: adding address fec0::5054:ff:fe12:3456/641019vm-test-run-scheduled-effects> buildbot # [   14.069650] dhcpcd[975]: eth0: adding route to fec0::/641020vm-test-run-scheduled-effects> buildbot # [   14.071307] dhcpcd[975]: eth0: adding default route via fe80::21021vm-test-run-scheduled-effects> buildbot # [   14.411317] postgresql-pre-start[1066]: selecting default time zone ... UTC1022vm-test-run-scheduled-effects> buildbot # [   14.416680] postgresql-pre-start[1066]: creating configuration files ... ok1023vm-test-run-scheduled-effects> buildbot # [   14.664946] postgresql-pre-start[1066]: running bootstrap script ... ok1024vm-test-run-scheduled-effects> buildbot # [   15.317571] postgresql-pre-start[1066]: performing post-bootstrap initialization ... ok1025vm-test-run-scheduled-effects> buildbot # [   15.539213] postgresql-pre-start[1066]: syncing data to disk ... ok1026vm-test-run-scheduled-effects> buildbot # [   15.541697] postgresql-pre-start[1066]: initdb: warning: enabling "trust" authentication for local connections1027vm-test-run-scheduled-effects> buildbot # [   15.544090] postgresql-pre-start[1066]: 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.1028vm-test-run-scheduled-effects> buildbot # [   15.547682] postgresql-pre-start[1066]: Success. You can now start the database server using:1029vm-test-run-scheduled-effects> buildbot # [   15.549653] postgresql-pre-start[1066]:     pg_ctl -D /var/lib/postgresql/17 -l logfile start1030vm-test-run-scheduled-effects> buildbot # [   15.688519] postgres[1172]: [1172] LOG:  starting PostgreSQL 17.10 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit1031vm-test-run-scheduled-effects> buildbot # [   15.702650] postgres[1172]: [1172] LOG:  listening on IPv6 address "::1", port 54321032vm-test-run-scheduled-effects> buildbot # [   15.704600] postgres[1172]: [1172] LOG:  listening on IPv4 address "127.0.0.1", port 54321033vm-test-run-scheduled-effects> buildbot # [   15.708521] postgres[1172]: [1172] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"1034vm-test-run-scheduled-effects> buildbot # [   15.721975] postgres[1178]: [1178] LOG:  database system was shut down at 2026-06-07 06:20:05 GMT1035vm-test-run-scheduled-effects> buildbot # [   15.730632] postgres[1172]: [1172] LOG:  database system is ready to accept connections1036vm-test-run-scheduled-effects> buildbot # [   15.737312] systemd[1]: Started PostgreSQL Server.1037vm-test-run-scheduled-effects> buildbot # [   15.743327] systemd[1]: Starting PostgreSQL Setup Scripts...1038vm-test-run-scheduled-effects> buildbot # [   15.957144] postgresql-setup-start[1189]: CREATE DATABASE1039vm-test-run-scheduled-effects> buildbot # [   16.013282] postgresql-setup-start[1194]: CREATE ROLE1040vm-test-run-scheduled-effects> buildbot # [   16.041714] postgresql-setup-start[1196]: ALTER DATABASE1041vm-test-run-scheduled-effects> buildbot # [   16.049329] systemd[1]: Finished PostgreSQL Setup Scripts.1042vm-test-run-scheduled-effects> buildbot # [   16.052412] systemd[1]: Reached target PostgreSQL.1043vm-test-run-scheduled-effects> buildbot # [   16.057398] systemd[1]: Starting Buildbot Continuous Integration Server....1044vm-test-run-scheduled-effects> buildbot # [   16.126517] buildbot-master-pre-start[1201]: mkdir: created directory '/var/lib/buildbot/master'1045vm-test-run-scheduled-effects> buildbot # [   18.477108] dhcpcd[975]: eth0: leased 10.0.2.15 for 86400 seconds1046vm-test-run-scheduled-effects> buildbot # [   18.479392] dhcpcd[975]: eth0: adding route to 10.0.2.0/241047vm-test-run-scheduled-effects> buildbot # [   18.480935] dhcpcd[975]: eth0: adding default route via 10.0.2.21048vm-test-run-scheduled-effects> buildbot # [   18.611629] systemd[1]: Started DHCP Client.1049vm-test-run-scheduled-effects> buildbot # [   24.235586] buildbot-master-pre-start[1203]: updating existing installation1050vm-test-run-scheduled-effects> buildbot # [   24.238328] buildbot-master-pre-start[1203]: not touching existing buildbot.tac1051vm-test-run-scheduled-effects> buildbot # [   24.241111] buildbot-master-pre-start[1203]: creating buildbot.tac.new instead1052vm-test-run-scheduled-effects> buildbot # [   24.243136] buildbot-master-pre-start[1203]: creating /var/lib/buildbot/master/master.cfg.sample1053vm-test-run-scheduled-effects> buildbot # [   24.246121] buildbot-master-pre-start[1203]: creating database (postgresql://@/buildbot)1054vm-test-run-scheduled-effects> buildbot # [   24.248270] buildbot-master-pre-start[1203]: buildmaster configured in /var/lib/buildbot/master1055vm-test-run-scheduled-effects> buildbot # [   24.437183] systemd[1]: Started Buildbot Continuous Integration Server..1056vm-test-run-scheduled-effects> buildbot # [   24.443945] systemd[1]: Started Buildbot Worker..1057vm-test-run-scheduled-effects> buildbot # [   24.445778] systemd[1]: Reached target Multi-User System.1058vm-test-run-scheduled-effects> buildbot # [   24.449078] systemd[1]: Startup finished in 953ms (kernel) + 5.207s (initrd) + 18.286s (userspace) = 24.447s.1059vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit multi-user.target, in 12.33 seconds)1060vm-test-run-scheduled-effects> subtest: Master and worker services start1061vm-test-run-scheduled-effects> buildbot: waiting for unit buildbot-master.service1062vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit buildbot-master.service, in 0.08 seconds)1063vm-test-run-scheduled-effects> buildbot: waiting for unit buildbot-worker.service1064vm-test-run-scheduled-effects> buildbot: (finished: waiting for unit buildbot-worker.service, in 0.07 seconds)1065vm-test-run-scheduled-effects> buildbot: waiting for TCP port 8010 on localhost1066vm-test-run-scheduled-effects> buildbot # [   26.240173] twistd[1331]: Starting worker local-worker-0001067vm-test-run-scheduled-effects> buildbot # [   26.241853] twistd[1331]: 2026-06-07T06:20:15+0000 [-] Loading /nix/store/zxbh9svi0g0i80pg7z3gd6hmk17ck3yf-buildbot_nix/buildbot_nix/worker.py...1068vm-test-run-scheduled-effects> buildbot # [   26.245475] twistd[1331]: 2026-06-07T06:20:16+0000 [-] Loaded.1069vm-test-run-scheduled-effects> buildbot # [   26.247566] twistd[1331]: 2026-06-07T06:20:16+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.1070vm-test-run-scheduled-effects> buildbot # [   26.251922] twistd[1331]: 2026-06-07T06:20:16+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] reactor class: twisted.internet.epollreactor.EPollReactor.1071vm-test-run-scheduled-effects> buildbot # [   26.256188] twistd[1331]: 2026-06-07T06:20:16+0000 [-] Starting Worker -- version: 2026.05.221072vm-test-run-scheduled-effects> buildbot # [   26.258766] twistd[1331]: 2026-06-07T06:20:16+0000 [-] recording hostname in twistd.hostname1073vm-test-run-scheduled-effects> buildbot # [   26.260859] twistd[1331]: 2026-06-07T06:20:16+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x730f1f3d0590>1074vm-test-run-scheduled-effects> buildbot # [   26.274823] twistd[1331]: 2026-06-07T06:20:16+0000 [twisted.application._client_service.ClientService#info] Scheduling retry 1 to connect <twisted.internet.endpoints.TCP4ClientEndpoint object at 0x730f1f3d0ad0> in 2.1440964821665194 seconds.1075vm-test-run-scheduled-effects> buildbot # [   26.279557] twistd[1331]: 2026-06-07T06:20:16+0000 [buildbot_worker.pb.BotFactory#info] Stopping factory <buildbot_worker.pb.BotFactory object at 0x730f1f3d0590>1076vm-test-run-scheduled-effects> buildbot # [   28.421198] twistd[1331]: 2026-06-07T06:20:18+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x730f1f3d0590>1077vm-test-run-scheduled-effects> buildbot # [   28.427305] twistd[1331]: 2026-06-07T06:20:18+0000 [twisted.application._client_service.ClientService#info] Scheduling retry 2 to connect <twisted.internet.endpoints.TCP4ClientEndpoint object at 0x730f1f3d0ad0> in 2.9916890214197114 seconds.1078vm-test-run-scheduled-effects> buildbot # [   28.432104] twistd[1331]: 2026-06-07T06:20:18+0000 [buildbot_worker.pb.BotFactory#info] Stopping factory <buildbot_worker.pb.BotFactory object at 0x730f1f3d0590>1079vm-test-run-scheduled-effects> buildbot # [   29.146259] twistd[1330]: 2026-06-07T06:20:15+0000 [-] Loading /var/lib/buildbot/master/buildbot.tac...1080vm-test-run-scheduled-effects> buildbot # [   29.149258] twistd[1330]: 2026-06-07T06:20:19+0000 [-] Loaded.1081vm-test-run-scheduled-effects> buildbot # [   29.150849] twistd[1330]: 2026-06-07T06:20:19+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.1082vm-test-run-scheduled-effects> buildbot # [   29.154955] twistd[1330]: 2026-06-07T06:20:19+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] reactor class: twisted.internet.epollreactor.EPollReactor.1083vm-test-run-scheduled-effects> buildbot # [   29.158243] twistd[1330]: 2026-06-07T06:20:19+0000 [-] Starting BuildMaster -- buildbot.version: 4.3.01084vm-test-run-scheduled-effects> buildbot # [   29.174821] twistd[1330]: 2026-06-07T06:20:19+0000 [-] Loading configuration from '/nix/store/lrw01m59h52qsb3jnqd1wm6qfaj4z4sv-master.cfg'1085vm-test-run-scheduled-effects> buildbot # [   30.371328] twistd[1330]: 2026-06-07T06:20:20+0000 [-] Setting up database with URL 'postgresql://@/buildbot'1086vm-test-run-scheduled-effects> buildbot # [   30.506783] twistd[1330]: 2026-06-07T06:20:20+0000 [-] adding 9 new builders, removing 01087vm-test-run-scheduled-effects> buildbot # [   30.620138] twistd[1330]: 2026-06-07T06:20:20+0000 [-] adding 3 new services, removing 01088vm-test-run-scheduled-effects> buildbot # [   30.766465] twistd[1330]: 2026-06-07T06:20:21+0000 [-] adding 1 new change_sources, removing 01089vm-test-run-scheduled-effects> buildbot # [   30.772099] twistd[1330]: 2026-06-07T06:20:21+0000 [-] gitpoller: using workdir '/var/lib/buildbot/master/gitpoller-work'1090vm-test-run-scheduled-effects> buildbot # [   30.785173] twistd[1330]: 2026-06-07T06:20:21+0000 [-] adding 14 new schedulers, removing 01091vm-test-run-scheduled-effects> buildbot # [   30.982068] twistd[1330]: 2026-06-07T06:20:21+0000 [-] BuildbotSite starting on 80101092vm-test-run-scheduled-effects> buildbot # [   30.984258] twistd[1330]: 2026-06-07T06:20:21+0000 [buildbot.www.service.BuildbotSite#info] Starting factory <buildbot.www.service.BuildbotSite object at 0x7cc600130980>1093vm-test-run-scheduled-effects> buildbot # [   30.988282] twistd[1330]: 2026-06-07T06:20:21+0000 [-] adding 5 new workers, removing 01094vm-test-run-scheduled-effects> buildbot # [   30.999106] twistd[1330]: 2026-06-07T06:20:21+0000 [-] PBServerFactory starting on 99891095vm-test-run-scheduled-effects> buildbot # [   31.001084] twistd[1330]: 2026-06-07T06:20:21+0000 [twisted.spread.pb.PBServerFactory#info] Starting factory <twisted.spread.pb.PBServerFactory object at 0x7cc600131400>1096vm-test-run-scheduled-effects> buildbot # [   31.026795] twistd[1330]: 2026-06-07T06:20:21+0000 [-] Starting Worker -- version: 2026.05.221097vm-test-run-scheduled-effects> buildbot # [   31.028839] twistd[1330]: 2026-06-07T06:20:21+0000 [-] recording hostname in twistd.hostname1098vm-test-run-scheduled-effects> buildbot # [   31.030819] twistd[1330]: 2026-06-07T06:20:21+0000 [-] message from master: attached1099vm-test-run-scheduled-effects> buildbot # [   31.034121] twistd[1330]: 2026-06-07T06:20:21+0000 [-] Got workerinfo from '__Janitor'1100vm-test-run-scheduled-effects> buildbot # [   31.044887] twistd[1330]: 2026-06-07T06:20:21+0000 [-] bot attached1101vm-test-run-scheduled-effects> buildbot # [   31.047643] twistd[1330]: 2026-06-07T06:20:21+0000 [-] Worker __Janitor attached to __Janitor1102vm-test-run-scheduled-effects> buildbot # [   31.050254] twistd[1330]: 2026-06-07T06:20:21+0000 [-] message from master: attached1103vm-test-run-scheduled-effects> buildbot # [   31.095831] sshd-session[1399]: Accepted publickey for root from ::1 port 57290 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81104vm-test-run-scheduled-effects> buildbot # [   31.106547] twistd[1330]: 2026-06-07T06:20:21+0000 [-] BuildMaster is running1105vm-test-run-scheduled-effects> buildbot # [   31.118589] sshd-session[1399]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1106vm-test-run-scheduled-effects> buildbot # [   31.153096] systemd[1]: Created slice Slice /user/0.1107vm-test-run-scheduled-effects> buildbot # [   31.156802] systemd[1]: Starting User Runtime Directory /run/user/0...1108vm-test-run-scheduled-effects> buildbot # [   31.171747] systemd-logind[896]: New session '1' of user 'root' with class 'user' and type 'tty'.1109vm-test-run-scheduled-effects> buildbot # [   31.208191] systemd[1]: Finished User Runtime Directory /run/user/0.1110vm-test-run-scheduled-effects> buildbot # [   31.218315] systemd[1]: Starting User Manager for UID 0...1111vm-test-run-scheduled-effects> buildbot # [   31.266208] (systemd)[1404]: pam_unix(systemd-user:session): session opened for user root(uid=0) by (uid=0)1112vm-test-run-scheduled-effects> buildbot # [   31.275085] systemd-logind[896]: New session '2' of user 'root' with class 'manager-early' and type 'unspecified'.1113vm-test-run-scheduled-effects> buildbot # [   31.423262] twistd[1331]: 2026-06-07T06:20:21+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x730f1f3d0590>1114vm-test-run-scheduled-effects> buildbot # [   31.433796] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] worker 'local-worker-000' attaching from IPv4Address(type='TCP', host='127.0.0.1', port=60810)1115vm-test-run-scheduled-effects> buildbot # [   31.438534] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1116vm-test-run-scheduled-effects> buildbot # [   31.445343] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Got workerinfo from 'local-worker-000'1117vm-test-run-scheduled-effects> buildbot # [   31.455848] twistd[1330]: 2026-06-07T06:20:21+0000 [-] bot attached1118vm-test-run-scheduled-effects> buildbot # [   31.460994] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/run-scheduled-effect1119vm-test-run-scheduled-effects> buildbot # [   31.464302] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-failed-eval1120vm-test-run-scheduled-effects> buildbot # [   31.467854] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-eval1121vm-test-run-scheduled-effects> buildbot # [   31.470800] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-build1122vm-test-run-scheduled-effects> buildbot # [   31.474067] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-cached-failure1123vm-test-run-scheduled-effects> buildbot # [   31.477382] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-dependency-failed1124vm-test-run-scheduled-effects> buildbot # [   31.480857] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/run-effect1125vm-test-run-scheduled-effects> buildbot # [   31.483864] twistd[1330]: 2026-06-07T06:20:21+0000 [Broker,0,127.0.0.1] Worker local-worker-000 attached to test-flake/nix-register-gcroot1126vm-test-run-scheduled-effects> buildbot # [   31.488139] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1127vm-test-run-scheduled-effects> buildbot # [   31.490322] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1128vm-test-run-scheduled-effects> buildbot # [   31.492520] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1129vm-test-run-scheduled-effects> buildbot # [   31.494629] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1130vm-test-run-scheduled-effects> buildbot # [   31.496770] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1131vm-test-run-scheduled-effects> buildbot # [   31.499386] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1132vm-test-run-scheduled-effects> buildbot # [   31.501720] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1133vm-test-run-scheduled-effects> buildbot # [   31.504396] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] message from master: attached1134vm-test-run-scheduled-effects> buildbot # [   31.528144] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] Connected to buildmaster; worker is ready1135vm-test-run-scheduled-effects> buildbot # [   31.533121] twistd[1331]: 2026-06-07T06:20:21+0000 [Broker,client] sending application-level keepalives every 600 seconds1136vm-test-run-scheduled-effects> buildbot # [   31.740760] systemd[1404]: Queued start job for default target Main User Target.1137vm-test-run-scheduled-effects> buildbot # [   31.744643] systemd[1404]: Created slice User Application Slice.1138vm-test-run-scheduled-effects> buildbot # [   31.746939] systemd[1404]: Started Daily Cleanup of User's Temporary Directories.1139vm-test-run-scheduled-effects> buildbot # [   31.749095] systemd[1404]: Reached target Paths.1140vm-test-run-scheduled-effects> buildbot # [   31.750965] systemd[1404]: Reached target Timers.1141vm-test-run-scheduled-effects> buildbot # [   31.754987] systemd[1404]: Starting D-Bus User Message Bus Socket...1142vm-test-run-scheduled-effects> buildbot # [   31.758374] systemd[1404]: Starting Create User Files and Directories...1143vm-test-run-scheduled-effects> buildbot # [   31.819316] systemd[1404]: Finished Create User Files and Directories.1144vm-test-run-scheduled-effects> buildbot # [   31.864602] systemd[1404]: Listening on D-Bus User Message Bus Socket.1145vm-test-run-scheduled-effects> buildbot # [   31.866474] systemd[1404]: Reached target Sockets.1146vm-test-run-scheduled-effects> buildbot # [   31.867857] systemd[1404]: Reached target Basic System.1147vm-test-run-scheduled-effects> buildbot # [   31.872402] systemd[1404]: Run user-specific NixOS activation skipped, unmet condition check ConditionUser=!@system1148vm-test-run-scheduled-effects> buildbot # [   31.876389] systemd[1404]: Reached target Main User Target.1149vm-test-run-scheduled-effects> buildbot # [   31.878937] systemd[1404]: Startup finished in 560ms.1150vm-test-run-scheduled-effects> buildbot # [   31.881735] systemd[1]: Started User Manager for UID 0.1151vm-test-run-scheduled-effects> buildbot # [   31.883687] systemd[1]: Started Session 1 of User root.1152vm-test-run-scheduled-effects> buildbot # Connection to localhost (127.0.0.1) 8010 port [tcp/*] succeeded!1153vm-test-run-scheduled-effects> buildbot: (finished: waiting for TCP port 8010 on localhost, in 6.40 seconds)1154vm-test-run-scheduled-effects> buildbot: waiting for success: curl --fail --head http://localhost:80101155vm-test-run-scheduled-effects> buildbot # [   31.928471] sshd-session[1426]: Received disconnect from ::1 port 57290:11: disconnected by user1156vm-test-run-scheduled-effects> buildbot # [   31.933130] sshd-session[1426]: Disconnected from user root ::1 port 572901157vm-test-run-scheduled-effects> buildbot # [   31.935187] sshd-session[1399]: pam_unix(sshd:session): session closed for user root1158vm-test-run-scheduled-effects> buildbot # [   31.944379] systemd[1]: session-1.scope: Deactivated successfully.1159vm-test-run-scheduled-effects> buildbot # [   31.948580] systemd-logind[896]: Session 1 logged out. Waiting for processes to exit.1160vm-test-run-scheduled-effects> buildbot # [   31.951318] systemd-logind[896]: Removed session 1.1161vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1162vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1163vm-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                              01164vm-test-run-scheduled-effects> buildbot: (finished: waiting for success: curl --fail --head http://localhost:8010, in 0.19 seconds)1165vm-test-run-scheduled-effects> (finished: subtest: Master and worker services start, in 6.75 seconds)1166vm-test-run-scheduled-effects> subtest: Project is registered1167vm-test-run-scheduled-effects> buildbot: waiting for success: curl http://localhost:8010/api/v2/projects1168vm-test-run-scheduled-effects> buildbot # [   32.152567] sshd-session[1435]: Accepted publickey for root from ::1 port 57304 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81169vm-test-run-scheduled-effects> buildbot #   % Total    % Received [   32.173223] sshd-session[1435]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1170vm-test-run-scheduled-effects> buildbot # % Xferd  Average Speed  Time    Time    Time   Current1171vm-test-run-scheduled-effects> buildbot #              [   32.193716] systemd-logind[896]: New session '3' of user 'root' with class 'user' and type 'tty'.1172vm-test-run-scheduled-effects> buildbot #     [   32.197458] systemd[1]: Started Session 3 of User root.1173vm-test-run-scheduled-effects> buildbot #                 Dload  Upload  Total   Spent   Left   Speed1174vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    266 100    266   0      0   4065      0                              0100    266 100    266   0      0   3345      0                              0100    266 100    266   0      0   2859      0                              01175vm-test-run-scheduled-effects> buildbot: (finished: waiting for success: curl http://localhost:8010/api/v2/projects, in 0.18 seconds)1176vm-test-run-scheduled-effects> (finished: subtest: Project is registered, in 0.18 seconds)1177vm-test-run-scheduled-effects> subtest: CLI list-schedules works1178vm-test-run-scheduled-effects> buildbot: must succeed: 1179vm-test-run-scheduled-effects>         cd /tmp/test-flake1180vm-test-run-scheduled-effects>         buildbot-effects list-schedules1181vm-test-run-scheduled-effects>     1182vm-test-run-scheduled-effects> buildbot # [   32.290871] sshd-session[1442]: Received disconnect from ::1 port 57304:11: disconnected by user1183vm-test-run-scheduled-effects> buildbot # [   32.294704] sshd-session[1442]: Disconnected from user root ::1 port 573041184vm-test-run-scheduled-effects> buildbot # [   32.297749] sshd-session[1435]: pam_unix(sshd:session): session closed for user root1185vm-test-run-scheduled-effects> buildbot # [   32.306506] systemd[1]: session-3.scope: Deactivated successfully.1186vm-test-run-scheduled-effects> buildbot # [   32.312448] systemd-logind[896]: Session 3 logged out. Waiting for processes to exit.1187vm-test-run-scheduled-effects> buildbot # [   32.317817] systemd-logind[896]: Removed session 3.1188vm-test-run-scheduled-effects> buildbot # [   32.343158] twistd[1330]: 2026-06-07T06:20:22+0000 [-] gitpoller: processing changes from "ssh://root@localhost/srv/repos/test-flake.git"1189vm-test-run-scheduled-effects> buildbot: (finished: must succeed: 1190vm-test-run-scheduled-effects>         cd /tmp/test-flake1191vm-test-run-scheduled-effects>         buildbot-effects list-schedules1192vm-test-run-scheduled-effects>     , in 0.58 seconds)1193vm-test-run-scheduled-effects> (finished: subtest: CLI list-schedules works, in 0.58 seconds)1194vm-test-run-scheduled-effects> subtest: Push a new commit to trigger build1195vm-test-run-scheduled-effects> buildbot: must succeed: 1196vm-test-run-scheduled-effects>         cd /tmp/test-flake1197vm-test-run-scheduled-effects>         echo "# trigger rebuild" >> flake.nix1198vm-test-run-scheduled-effects>         git add flake.nix1199vm-test-run-scheduled-effects>         git commit -m "Trigger build"1200vm-test-run-scheduled-effects>         git push origin master1201vm-test-run-scheduled-effects>     1202vm-test-run-scheduled-effects> buildbot # Enumerating objects: 5, done.1203vm-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.1204vm-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.1205vm-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 | 148.00 KiB/s, done.1206vm-test-run-scheduled-effects> buildbot # Total 3 (delta 2), reused 0 (delta 0), pack-reused 0 (from 0)1207vm-test-run-scheduled-effects> buildbot # To /srv/repos/test-flake.git1208vm-test-run-scheduled-effects> buildbot #    9dba588..22d1cc8  master -> master1209vm-test-run-scheduled-effects> buildbot: (finished: must succeed: 1210vm-test-run-scheduled-effects>         cd /tmp/test-flake1211vm-test-run-scheduled-effects>         echo "# trigger rebuild" >> flake.nix1212vm-test-run-scheduled-effects>         git add flake.nix1213vm-test-run-scheduled-effects>         git commit -m "Trigger build"1214vm-test-run-scheduled-effects>         git push origin master1215vm-test-run-scheduled-effects>     , in 0.13 seconds)1216vm-test-run-scheduled-effects> (finished: subtest: Push a new commit to trigger build, in 0.13 seconds)1217vm-test-run-scheduled-effects> subtest: Wait for nix-eval build to complete1218vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1219vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1220vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1221vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1305      0                              0100     51 100     51   0      0   1034      0                              0100     51 100     51   0      0    850      0                              01222vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.12 seconds)1223vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1224vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1225vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1226vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1322      0                              0100     51 100     51   0      0   1050      0                              0100     51 100     51   0      0    872      0                              01227vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.15 seconds)1228vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1229vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1230vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1231vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1212      0                              0100     51 100     51   0      0    981      0                              0100     51 100     51   0      0    820      0                              01232vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1233vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1234vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1235vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1236vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1258      0                              0100     51 100     51   0      0   1009      0                              0100     51 100     51   0      0    843      0                              01237vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.15 seconds)1238vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1239vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1240vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1241vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1318      0                              0100     51 100     51   0      0   1045      0                              0100     51 100     51   0      0    869      0                              01242vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.15 seconds)1243vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1244vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1245vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1246vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1223      0                              0100     51 100     51   0      0    979      0                              0100     51 100     51   0      0    822      0                              01247vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.15 seconds)1248vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1249vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1250vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1251vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1132      0                              0100     51 100     51   0      0    920      0                              0100     51 100     51   0      0    778      0                              01252vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.16 seconds)1253vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1254vm-test-run-scheduled-effects> buildbot # [   41.057632] sshd-session[1510]: Accepted publickey for root from ::1 port 40798 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81255vm-test-run-scheduled-effects> buildbot # [   41.085792] sshd-session[1510]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1256vm-test-run-scheduled-effects> buildbot # [   41.099102] systemd-logind[896]: New session '4' of user 'root' with class 'user' and type 'tty'.1257vm-test-run-scheduled-effects> buildbot # [   41.102462] systemd[1]: Started Session 4 of User root.1258vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1259vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spe[   41.156789] sshd-session[1516]: Received disconnect from ::1 port 40798:11: disconnected by user1260vm-test-run-scheduled-effects> buildbot # [   41.159335] sshd-session[1516]: Disconnected from user root ::1 port 407981261vm-test-run-scheduled-effects> buildbot # nt   Left[   41.162311] sshd-session[1510]: pam_unix(sshd:session): session closed for user root1262vm-test-run-scheduled-effects> buildbot #    Speed1263vm-test-run-scheduled-effects> buildbot #   0      0   [   41.172186] systemd[1]: session-4.scope: Deactivated successfully.1264vm-test-run-scheduled-effects> buildbot # 0      0   0      0      0   [   41.184465] systemd-logind[896]: Session 4 logged out. Waiting for processes to exit.1265vm-test-run-scheduled-effects> buildbot # [   41.186444] systemd-logind[896]: Removed session 4.1266vm-test-run-scheduled-effects> buildbot #    0                              0100     51 100     51   0      0    598      0                              0100     51 100     51   0      0    510      0                              0100     51 100     51   0      0    449      0                              01267vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.22 seconds)1268vm-test-run-scheduled-effects> buildbot # [   41.423616] sshd-session[1521]: Accepted publickey for root from ::1 port 40808 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81269vm-test-run-scheduled-effects> buildbot # [   41.447942] sshd-session[1521]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1270vm-test-run-scheduled-effects> buildbot # [   41.460279] systemd-logind[896]: New session '5' of user 'root' with class 'user' and type 'tty'.1271vm-test-run-scheduled-effects> buildbot # [   41.464488] systemd[1]: Started Session 5 of User root.1272vm-test-run-scheduled-effects> buildbot # [   41.521839] sshd-session[1524]: Received disconnect from ::1 port 40808:11: disconnected by user1273vm-test-run-scheduled-effects> buildbot # [   41.524662] sshd-session[1524]: Disconnected from user root ::1 port 408081274vm-test-run-scheduled-effects> buildbot # [   41.528104] sshd-session[1521]: pam_unix(sshd:session): session closed for user root1275vm-test-run-scheduled-effects> buildbot # [   41.535134] systemd[1]: session-5.scope: Deactivated successfully.1276vm-test-run-scheduled-effects> buildbot # [   41.539839] systemd-logind[896]: Session 5 logged out. Waiting for processes to exit.1277vm-test-run-scheduled-effects> buildbot # [   41.544125] systemd-logind[896]: Removed session 5.1278vm-test-run-scheduled-effects> buildbot # [   41.564183] twistd[1330]: 2026-06-07T06:20:31+0000 [-] gitpoller: processing changes from "ssh://root@localhost/srv/repos/test-flake.git"1279vm-test-run-scheduled-effects> buildbot # [   41.600456] twistd[1330]: 2026-06-07T06:20:31+0000 [-] gitpoller: processing 1 changes: ['22d1cc8fa14a383dad519b0a3f3ad8d86767af47'] from "ssh://root@localhost/srv/repos/test-flake.git" branch "refs/heads/master"1280vm-test-run-scheduled-effects> buildbot # [   41.686952] twistd[1330]: 2026-06-07T06:20:32+0000 [-] added change with revision 22d1cc8fa14a383dad519b0a3f3ad8d86767af47 to database1281vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1282vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1283vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1284vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1240      0                              0100     51 100     51   0      0    990      0                              0100     51 100     51   0      0    829      0                              01285vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.15 seconds)1286vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1287vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1288vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1289vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1398      0                              0100     51 100     51   0      0   1093      0                              0100     51 100     51   0      0    899      0                              01290vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.12 seconds)1291vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1292vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1293vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1294vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1336      0                              0100     51 100     51   0      0   1059      0                              0100     51 100     51   0      0    877      0                              01295vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.15 seconds)1296vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1297vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1298vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1299vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100     51 100     51   0      0   1191      0                              0100     51 100     51   0      0    953      0                              0100     51 100     51   0      0    806      0                              01300vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.15 seconds)1301vm-test-run-scheduled-effects> buildbot # [   46.737278] twistd[1330]: 2026-06-07T06:20:37+0000 [-] added buildset 1 to database1302vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1303vm-test-run-scheduled-effects> buildbot # [   46.898734] twistd[1330]: 2026-06-07T06:20:37+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>1304vm-test-run-scheduled-effects> buildbot # [   46.903296] twistd[1330]: 2026-06-07T06:20:37+0000 [-] <Build test-flake/nix-eval number:None results:success>.startBuild1305vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1306vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1307vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    400 100    400   0      0   7817      0                              0100    400 100    400   0      0   6103      0                              0100    400 100    400   0      0   4895      0                              01308vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.19 seconds)1309vm-test-run-scheduled-effects> buildbot # [   47.022678] twistd[1330]: 2026-06-07T06:20:37+0000 [-] acquireLocks(worker <Worker 'local-worker-000'>, locks [])1310vm-test-run-scheduled-effects> buildbot # [   47.027846] twistd[1330]: 2026-06-07T06:20:37+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>1311vm-test-run-scheduled-effects> buildbot # [   47.032784] twistd[1330]: 2026-06-07T06:20:37+0000 [-] sending ping1312vm-test-run-scheduled-effects> buildbot # [   47.035309] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] message from master: ping1313vm-test-run-scheduled-effects> buildbot # [   47.037765] twistd[1330]: 2026-06-07T06:20:37+0000 [Broker,0,127.0.0.1] ping finished: success1314vm-test-run-scheduled-effects> buildbot # [   47.062764] twistd[1330]: 2026-06-07T06:20:37+0000 [-] <RemoteShellCommand '['git', '--version']'>: RemoteCommand.run [0]1315vm-test-run-scheduled-effects> buildbot # [   47.066491] twistd[1330]: 2026-06-07T06:20:37+0000 [-] command '['git', '--version']' in dir 'build'1316vm-test-run-scheduled-effects> buildbot # [   47.070257] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 0): startCommand:shell1317vm-test-run-scheduled-effects> buildbot # [   47.072837] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command ['git', '--version']): RunProcess._startCommand1318vm-test-run-scheduled-effects> buildbot # [   47.075538] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command ['git', '--version']):  git --version1319vm-test-run-scheduled-effects> buildbot # [   47.081093] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command ['git', '--version']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1320vm-test-run-scheduled-effects> buildbot # [   47.084697] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command ['git', '--version']):   watching logfiles {}1321vm-test-run-scheduled-effects> buildbot # [   47.087182] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command ['git', '--version']):   argv: [b'git', b'--version']1322vm-test-run-scheduled-effects> buildbot # [   47.089749] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command ['git', '--version']):   using PTY: False1323vm-test-run-scheduled-effects> buildbot # [   47.107306] twistd[1331]: 2026-06-07T06:20:37+0000 [-] (command ['git', '--version']): command finished with signal None, exit code 0, elapsedTime: 0.0274421324vm-test-run-scheduled-effects> buildbot # [   47.110705] twistd[1331]: 2026-06-07T06:20:37+0000 [-] (command 0): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f3d2900>1325vm-test-run-scheduled-effects> buildbot # [   47.140105] twistd[1330]: 2026-06-07T06:20:37+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['git', '--version']'> rc=01326vm-test-run-scheduled-effects> buildbot # [   47.185349] twistd[1330]: 2026-06-07T06:20:37+0000 [-] <RemoteCommand 'stat' at 137189845910928>: RemoteCommand.run [1]1327vm-test-run-scheduled-effects> buildbot # [   47.190244] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 1): startCommand:stat1328vm-test-run-scheduled-effects> buildbot # [   47.192300] twistd[1331]: 2026-06-07T06:20:37+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'1329vm-test-run-scheduled-effects> buildbot # [   47.197833] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 1): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.fs.StatFile object at 0x730f1f3d1400>1330vm-test-run-scheduled-effects> buildbot # [   47.203140] twistd[1330]: 2026-06-07T06:20:37+0000 [Broker,0,127.0.0.1] <RemoteCommand 'stat' at 137189845910928> rc=21331vm-test-run-scheduled-effects> buildbot # [   47.217599] twistd[1330]: 2026-06-07T06:20:37+0000 [-] <RemoteCommand 'mkdir' at 137189846894864>: RemoteCommand.run [2]1332vm-test-run-scheduled-effects> buildbot # [   47.248116] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 2): startCommand:mkdir1333vm-test-run-scheduled-effects> buildbot # [   47.250699] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 2): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.fs.MakeDirectory object at 0x730f1f3d1160>1334vm-test-run-scheduled-effects> buildbot # [   47.256314] twistd[1330]: 2026-06-07T06:20:37+0000 [Broker,0,127.0.0.1] <RemoteCommand 'mkdir' at 137189846894864> rc=01335vm-test-run-scheduled-effects> buildbot # [   47.265174] twistd[1330]: 2026-06-07T06:20:37+0000 [-] <RemoteCommand 'downloadFile' at 137189847513552>: RemoteCommand.run [3]1336vm-test-run-scheduled-effects> buildbot # [   47.297218] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 3): startCommand:downloadFile1337vm-test-run-scheduled-effects> buildbot # [   47.301895] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 3): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.transfer.WorkerFileDownloadCommand object at 0x730f1f3d01a0>1338vm-test-run-scheduled-effects> buildbot # [   47.306734] twistd[1330]: 2026-06-07T06:20:37+0000 [Broker,0,127.0.0.1] <RemoteCommand 'downloadFile' at 137189847513552> rc=01339vm-test-run-scheduled-effects> buildbot # [   47.316563] twistd[1330]: 2026-06-07T06:20:37+0000 [-] <RemoteCommand 'listdir' at 137189847513872>: RemoteCommand.run [4]1340vm-test-run-scheduled-effects> buildbot # [   47.351822] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 4): startCommand:listdir1341vm-test-run-scheduled-effects> buildbot # [   47.354843] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 4): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.fs.ListDir object at 0x730f1f3d12b0>1342vm-test-run-scheduled-effects> buildbot # [   47.359379] twistd[1330]: 2026-06-07T06:20:37+0000 [Broker,0,127.0.0.1] <RemoteCommand 'listdir' at 137189847513872> rc=01343vm-test-run-scheduled-effects> buildbot # [   47.369822] twistd[1330]: 2026-06-07T06:20:37+0000 [-] No git repo present, making full clone1344vm-test-run-scheduled-effects> buildbot # [   47.371796] twistd[1330]: 2026-06-07T06:20:37+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]1345vm-test-run-scheduled-effects> buildbot # [   47.377895] twistd[1330]: 2026-06-07T06:20:37+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'1346vm-test-run-scheduled-effects> buildbot # [   47.405107] twistd[1331]: 2026-06-07T06:20:37+0000 [Broker,client] (command 5): startCommand:shell1347vm-test-run-scheduled-effects> buildbot # [   47.407280] twistd[1331]: 2026-06-07T06:20:37+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._startCommand1348vm-test-run-scheduled-effects> buildbot # [   47.413434] twistd[1331]: 2026-06-07T06:20:37+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 . --progress1349vm-test-run-scheduled-effects> buildbot # [   47.434630] twistd[1331]: 2026-06-07T06:20:37+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)1350vm-test-run-scheduled-effects> buildbot # [   47.442531] twistd[1331]: 2026-06-07T06:20:37+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 {}1351vm-test-run-scheduled-effects> buildbot # [   47.448789] twistd[1331]: 2026-06-07T06:20:37+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']1352vm-test-run-scheduled-effects> buildbot # [   47.459284] twistd[1331]: 2026-06-07T06:20:37+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: False1353vm-test-run-scheduled-effects> buildbot # [   47.665354] sshd-session[1559]: Accepted publickey for root from ::1 port 53996 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81354vm-test-run-scheduled-effects> buildbot # [   47.686926] sshd-session[1559]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1355vm-test-run-scheduled-effects> buildbot # [   47.699364] systemd-logind[896]: New session '6' of user 'root' with class 'user' and type 'tty'.1356vm-test-run-scheduled-effects> buildbot # [   47.703437] systemd[1]: Started Session 6 of User root.1357vm-test-run-scheduled-effects> buildbot # [   47.760329] sshd-session[1562]: Received disconnect from ::1 port 53996:11: disconnected by user1358vm-test-run-scheduled-effects> buildbot # [   47.762690] sshd-session[1562]: Disconnected from user root ::1 port 539961359vm-test-run-scheduled-effects> buildbot # [   47.764743] sshd-session[1559]: pam_unix(sshd:session): session closed for user root1360vm-test-run-scheduled-effects> buildbot # [   47.772837] systemd[1]: session-6.scope: Deactivated successfully.1361vm-test-run-scheduled-effects> buildbot # [   47.778867] systemd-logind[896]: Session 6 logged out. Waiting for processes to exit.1362vm-test-run-scheduled-effects> buildbot # [   47.782213] systemd-logind[896]: Removed session 6.1363vm-test-run-scheduled-effects> buildbot # [   47.795315] twistd[1331]: 2026-06-07T06:20:38+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.3714401364vm-test-run-scheduled-effects> buildbot # [   47.803202] twistd[1331]: 2026-06-07T06:20:38+0000 [-] (command 5): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f3ed090>1365vm-test-run-scheduled-effects> buildbot # [   47.810427] twistd[1330]: 2026-06-07T06:20:38+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=01366vm-test-run-scheduled-effects> buildbot # [   47.840138] twistd[1330]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']'>: RemoteCommand.run [6]1367vm-test-run-scheduled-effects> buildbot # [   47.845699] twistd[1330]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']' in dir 'build'1368vm-test-run-scheduled-effects> buildbot # [   47.853106] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command 6): startCommand:shell1369vm-test-run-scheduled-effects> buildbot # [   47.858102] twistd[1331]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']): RunProcess._startCommand1370vm-test-run-scheduled-effects> buildbot # [   47.863635] twistd[1331]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']):  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 22d1cc8fa14a383dad519b0a3f3ad8d86767af471371vm-test-run-scheduled-effects> buildbot # [   47.871840] twistd[1331]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1372vm-test-run-scheduled-effects> buildbot # [   47.878636] twistd[1331]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']):   watching logfiles {}1373vm-test-run-scheduled-effects> buildbot # [   47.884161] twistd[1331]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']):   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'22d1cc8fa14a383dad519b0a3f3ad8d86767af47']1374vm-test-run-scheduled-effects> buildbot # [   47.892959] twistd[1331]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']):   using PTY: False1375vm-test-run-scheduled-effects> buildbot # [   47.919503] twistd[1331]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']): command finished with signal None, exit code 0, elapsedTime: 0.0624781376vm-test-run-scheduled-effects> buildbot # [   47.926095] twistd[1331]: 2026-06-07T06:20:38+0000 [-] (command 6): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f3ed450>1377vm-test-run-scheduled-effects> buildbot # [   47.946051] twistd[1330]: 2026-06-07T06:20:38+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', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47']'> rc=01378vm-test-run-scheduled-effects> buildbot # [   47.974712] twistd[1330]: 2026-06-07T06:20:38+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]1379vm-test-run-scheduled-effects> buildbot # [   47.980106] twistd[1330]: 2026-06-07T06:20:38+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'1380vm-test-run-scheduled-effects> buildbot # [   47.985956] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command 7): startCommand:shell1381vm-test-run-scheduled-effects> buildbot # [   47.989369] twistd[1331]: 2026-06-07T06:20:38+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._startCommand1382vm-test-run-scheduled-effects> buildbot # [   47.994917] twistd[1331]: 2026-06-07T06:20:38+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 --recursive1383vm-test-run-scheduled-effects> buildbot # [   48.003097] twistd[1331]: 2026-06-07T06:20:38+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)1384vm-test-run-scheduled-effects> buildbot # [   48.011201] twistd[1331]: 2026-06-07T06:20:38+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 {}1385vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1386vm-test-run-scheduled-effects> buildbot # [   48.016520] twistd[1331]: 2026-06-07T06:20:38+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']1387vm-test-run-scheduled-effects> buildbot # [   48.024770] twistd[1331]: 2026-06-07T06:20:38+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: False1388vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1389vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1390vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    401 100    401   0      0   7341      0                              0100    401 100    401   0      0   5792      0                              0100    401 100    401   0      0   4798      0                              01391vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.17 seconds)1392vm-test-run-scheduled-effects> buildbot # [   48.201603] twistd[1331]: 2026-06-07T06:20:38+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.1907491393vm-test-run-scheduled-effects> buildbot # [   48.208649] twistd[1331]: 2026-06-07T06:20:38+0000 [-] (command 7): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f392520>1394vm-test-run-scheduled-effects> buildbot # [   48.214540] twistd[1330]: 2026-06-07T06:20:38+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=01395vm-test-run-scheduled-effects> buildbot # [   48.238624] twistd[1330]: 2026-06-07T06:20:38+0000 [-] <RemoteShellCommand '['git', 'rev-parse', 'HEAD']'>: RemoteCommand.run [8]1396vm-test-run-scheduled-effects> buildbot # [   48.241273] twistd[1330]: 2026-06-07T06:20:38+0000 [-] command '['git', 'rev-parse', 'HEAD']' in dir 'build'1397vm-test-run-scheduled-effects> buildbot # [   48.244836] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command 8): startCommand:shell1398vm-test-run-scheduled-effects> buildbot # [   48.247601] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']): RunProcess._startCommand1399vm-test-run-scheduled-effects> buildbot # [   48.251094] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):  git rev-parse HEAD1400vm-test-run-scheduled-effects> buildbot # [   48.253665] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1401vm-test-run-scheduled-effects> buildbot # [   48.257417] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):   watching logfiles {}1402vm-test-run-scheduled-effects> buildbot # [   48.261892] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):   argv: [b'git', b'rev-parse', b'HEAD']1403vm-test-run-scheduled-effects> buildbot # [   48.264800] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['git', 'rev-parse', 'HEAD']):   using PTY: False1404vm-test-run-scheduled-effects> buildbot # [   48.280294] twistd[1331]: 2026-06-07T06:20:38+0000 [-] (command ['git', 'rev-parse', 'HEAD']): command finished with signal None, exit code 0, elapsedTime: 0.0288201405vm-test-run-scheduled-effects> buildbot # [   48.283851] twistd[1331]: 2026-06-07T06:20:38+0000 [-] (command 8): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f392650>1406vm-test-run-scheduled-effects> buildbot # [   48.313215] twistd[1330]: 2026-06-07T06:20:38+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['git', 'rev-parse', 'HEAD']'> rc=01407vm-test-run-scheduled-effects> buildbot # [   48.340128] twistd[1330]: 2026-06-07T06:20:38+0000 [-] Got Git revision 22d1cc8fa14a383dad519b0a3f3ad8d86767af471408vm-test-run-scheduled-effects> buildbot # [   48.342521] twistd[1330]: 2026-06-07T06:20:38+0000 [-] <RemoteCommand 'rmdir' at 137189846040976>: RemoteCommand.run [9]1409vm-test-run-scheduled-effects> buildbot # [   48.359105] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command 9): startCommand:rmdir1410vm-test-run-scheduled-effects> buildbot # [   48.361493] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']): RunProcess._startCommand1411vm-test-run-scheduled-effects> buildbot # [   48.365493] twistd[1331]: 2026-06-07T06:20:38+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.buildbot1412vm-test-run-scheduled-effects> buildbot # [   48.372197] twistd[1331]: 2026-06-07T06:20:38+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)1413vm-test-run-scheduled-effects> buildbot # [   48.376540] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']):   watching logfiles {}1414vm-test-run-scheduled-effects> buildbot # [   48.380207] twistd[1331]: 2026-06-07T06:20:38+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']1415vm-test-run-scheduled-effects> buildbot # [   48.385227] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['rm', '-rf', '/var/lib/buildbot-worker/worker-000/.test-flake_nix-eval.build.buildbot']):   using PTY: False1416vm-test-run-scheduled-effects> buildbot # [   48.404311] twistd[1331]: 2026-06-07T06:20:38+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.0332501417vm-test-run-scheduled-effects> buildbot # [   48.409108] twistd[1331]: 2026-06-07T06:20:38+0000 [-] (command 9): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.fs.RemoveDirectory object at 0x730f1f3d30e0>1418vm-test-run-scheduled-effects> buildbot # [   48.434886] twistd[1330]: 2026-06-07T06:20:38+0000 [Broker,0,127.0.0.1] <RemoteCommand 'rmdir' at 137189846040976> rc=01419vm-test-run-scheduled-effects> buildbot # [   48.458078] twistd[1330]: 2026-06-07T06:20:38+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)): []1420vm-test-run-scheduled-effects> buildbot # [   48.486194] twistd[1330]: 2026-06-07T06:20:38+0000 [-]  step 'git' complete: success (None)1421vm-test-run-scheduled-effects> buildbot # [   48.495437] twistd[1330]: 2026-06-07T06:20:38+0000 [-] acquireLocks(step NixEvalCommand(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x7cc6005ecd70>, 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 0x7cc6005ed2b0>, gcroots_user='buildbot-worker', cache_failed_builds=False, show_trace=False), haltOnFailure=True, locks=[<buildbot.locks.LockAccess object at 0x7cc6005ee660>], 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 0x7cc6005ee660>)])1422vm-test-run-scheduled-effects> buildbot # [   48.519123] twistd[1330]: 2026-06-07T06:20:38+0000 [-] <RemoteShellCommand '['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']'>: RemoteCommand.run [10]1423vm-test-run-scheduled-effects> buildbot # [   48.522595] twistd[1330]: 2026-06-07T06:20:38+0000 [-] command '['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']' in dir 'build'1424vm-test-run-scheduled-effects> buildbot # [   48.527780] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command 10): startCommand:shell1425vm-test-run-scheduled-effects> buildbot # [   48.531040] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']): RunProcess._startCommand1426vm-test-run-scheduled-effects> buildbot # [   48.534788] twistd[1331]: 2026-06-07T06:20:38+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'1427vm-test-run-scheduled-effects> buildbot # [   48.541094] twistd[1331]: 2026-06-07T06:20:38+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)1428vm-test-run-scheduled-effects> buildbot # [   48.545715] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']):   watching logfiles {}1429vm-test-run-scheduled-effects> buildbot # [   48.549218] twistd[1331]: 2026-06-07T06:20:38+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']1430vm-test-run-scheduled-effects> buildbot # [   48.553768] twistd[1331]: 2026-06-07T06:20:38+0000 [Broker,client] (command ['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']):   using PTY: False1431vm-test-run-scheduled-effects> buildbot # [   48.580348] twistd[1331]: 2026-06-07T06:20:38+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.0402701432vm-test-run-scheduled-effects> buildbot # [   48.584777] twistd[1331]: 2026-06-07T06:20:38+0000 [-] (command 10): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f9b3e30>1433vm-test-run-scheduled-effects> buildbot # [   48.603246] twistd[1330]: 2026-06-07T06:20:38+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['sh', '-c', 'if [ -f buildbot-nix.toml ]; then cat buildbot-nix.toml; fi']'> rc=01434vm-test-run-scheduled-effects> buildbot # [   48.611763] twistd[1330]: 2026-06-07T06:20:38+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]1435vm-test-run-scheduled-effects> buildbot # [   48.619290] twistd[1330]: 2026-06-07T06:20:38+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'1436vm-test-run-scheduled-effects> buildbot # [   48.650537] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command 11): startCommand:shell1437vm-test-run-scheduled-effects> buildbot # [   48.653150] twistd[1331]: 2026-06-07T06:20:39+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._startCommand1438vm-test-run-scheduled-effects> buildbot # [   48.661091] twistd[1331]: 2026-06-07T06:20:39+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'1439vm-test-run-scheduled-effects> buildbot # [   48.675095] twistd[1331]: 2026-06-07T06:20:39+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)1440vm-test-run-scheduled-effects> buildbot # [   48.683771] twistd[1331]: 2026-06-07T06:20:39+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 {}1441vm-test-run-scheduled-effects> buildbot # [   48.691250] twistd[1331]: 2026-06-07T06:20:39+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']1442vm-test-run-scheduled-effects> buildbot # [   48.704138] twistd[1331]: 2026-06-07T06:20:39+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: False1443vm-test-run-scheduled-effects> buildbot # [   48.852807] systemd[1]: Started Nix Daemon.1444vm-test-run-scheduled-effects> buildbot # [   48.972717] nix-daemon[1607]: accepted connection from pid 1606, user buildbot-worker1445vm-test-run-scheduled-effects> buildbot # [   49.005908] twistd[1331]: 2026-06-07T06:20:39+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.3320861446vm-test-run-scheduled-effects> buildbot # [   49.015206] twistd[1331]: 2026-06-07T06:20:39+0000 [-] (command 11): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f3f4af0>1447vm-test-run-scheduled-effects> buildbot # [   49.022434] twistd[1330]: 2026-06-07T06:20:39+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=01448vm-test-run-scheduled-effects> buildbot # [   49.063041] twistd[1330]: 2026-06-07T06:20:39+0000 [-] releaseLocks(NixEvalCommand(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x7cc6005ecd70>, 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 0x7cc6005ed2b0>, gcroots_user='buildbot-worker', cache_failed_builds=False, show_trace=False), haltOnFailure=True, locks=[<buildbot.locks.LockAccess object at 0x7cc6005ee660>], 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 0x7cc6005ee660>)]1449vm-test-run-scheduled-effects> buildbot # [   49.084326] twistd[1330]: 2026-06-07T06:20:39+0000 [-]  step 'Evaluate flake' complete: success (None)1450vm-test-run-scheduled-effects> buildbot # [   49.113269] twistd[1330]: 2026-06-07T06:20:39+0000 [-] releaseLocks(BuildTrigger(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x7cc6005ecd70>, 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')): []1451vm-test-run-scheduled-effects> buildbot # [   49.128441] twistd[1330]: 2026-06-07T06:20:39+0000 [-]  step 'build flake' complete: success (None)1452vm-test-run-scheduled-effects> buildbot # [   49.143110] twistd[1330]: 2026-06-07T06:20:39+0000 [-] releaseLocks(ProcessSkippedBuilds(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x7cc6005ecd70>, gcroots_user='buildbot-worker', branch_config={}, outputs_path=None, name='Process skipped builds', doStepIf=<function nix_eval_config.<locals>.<lambda> at 0x7cc600644ae0>, hideStepIf=<function nix_eval_config.<locals>.<lambda> at 0x7cc600644b80>)): []1453vm-test-run-scheduled-effects> buildbot # [   49.155812] twistd[1330]: 2026-06-07T06:20:39+0000 [-]  step 'Process skipped builds' complete: skipped (None)1454vm-test-run-scheduled-effects> buildbot # [   49.169628] twistd[1330]: 2026-06-07T06:20:39+0000 [-] <RemoteShellCommand '['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']'>: RemoteCommand.run [12]1455vm-test-run-scheduled-effects> buildbot # [   49.174674] twistd[1330]: 2026-06-07T06:20:39+0000 [-] command '['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']' in dir 'build'1456vm-test-run-scheduled-effects> buildbot # [   49.182096] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command 12): startCommand:shell1457vm-test-run-scheduled-effects> buildbot # [   49.184263] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']): RunProcess._startCommand1458vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1459vm-test-run-scheduled-effects> buildbot # [   49.188108] twistd[1331]: 2026-06-07T06:20:39+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/1460vm-test-run-scheduled-effects> buildbot # [   49.192810] twistd[1331]: 2026-06-07T06:20:39+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)1461vm-test-run-scheduled-effects> buildbot # [   49.197751] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']):   watching logfiles {}1462vm-test-run-scheduled-effects> buildbot # [   49.203567] twistd[1331]: 2026-06-07T06:20:39+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/']1463vm-test-run-scheduled-effects> buildbot # [   49.208825] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['rm', '-rf', '/nix/var/nix/gcroots/per-user/buildbot-worker/test-flake/drvs/local-worker-000/']):   using PTY: False1464vm-test-run-scheduled-effects> buildbot # [   49.229108] twistd[1331]: 2026-06-07T06:20:39+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.0473281465vm-test-run-scheduled-effects> buildbot # [   49.234378] twistd[1331]: 2026-06-07T06:20:39+0000 [-] (command 12): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f3f4f30>1466vm-test-run-scheduled-effects> buildbot # [   49.261130] twistd[1330]: 2026-06-07T06:20:39+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=01467vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1468vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1469vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    401 100    401   0      0   3276      0                              0100    401 100    401   0      0   2904      0                              0100    401 100    401   0  [   49.444688] twistd[1330]: 2026-06-07T06:20:39+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)): []1470vm-test-run-scheduled-effects> buildbot #     0   2593      0                              01471vm-test-run-scheduled-effects> buildbot # [   49.464214] twistd[1330]: 2026-06-07T06:20:39+0000 [-]  step 'Cleanup drv paths' complete: success (None)1472vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.28 seconds)1473vm-test-run-scheduled-effects> buildbot # [   49.479053] twistd[1330]: 2026-06-07T06:20:39+0000 [-] <RemoteShellCommand '['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']'>: RemoteCommand.run [13]1474vm-test-run-scheduled-effects> buildbot # [   49.484745] twistd[1330]: 2026-06-07T06:20:39+0000 [-] command '['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']' in dir 'build'1475vm-test-run-scheduled-effects> buildbot # [   49.489988] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command 13): startCommand:shell1476vm-test-run-scheduled-effects> buildbot # [   49.492806] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']): RunProcess._startCommand1477vm-test-run-scheduled-effects> buildbot # [   49.497645] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):  buildbot-effects list --rev 22d1cc8fa14a383dad519b0a3f3ad8d86767af47 --branch master --repo test-flake1478vm-test-run-scheduled-effects> buildbot # [   49.503619] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1479vm-test-run-scheduled-effects> buildbot # [   49.511221] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):   watching logfiles {}1480vm-test-run-scheduled-effects> buildbot # [   49.515535] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):   argv: [b'buildbot-effects', b'list', b'--rev', b'22d1cc8fa14a383dad519b0a3f3ad8d86767af47', b'--branch', b'master', b'--repo', b'test-flake']1481vm-test-run-scheduled-effects> buildbot # [   49.521941] twistd[1331]: 2026-06-07T06:20:39+0000 [Broker,client] (command ['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):   using PTY: False1482vm-test-run-scheduled-effects> buildbot # [   49.893426] nix-daemon[1607]: accepted connection from pid 1619, user buildbot-worker1483vm-test-run-scheduled-effects> buildbot # [   49.927486] twistd[1331]: 2026-06-07T06:20:40+0000 [-] (command ['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']): command finished with signal None, exit code 0, elapsedTime: 0.4174711484vm-test-run-scheduled-effects> buildbot # [   49.932821] twistd[1331]: 2026-06-07T06:20:40+0000 [-] (command 13): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f404550>1485vm-test-run-scheduled-effects> buildbot # [   49.940229] twistd[1330]: 2026-06-07T06:20:40+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['buildbot-effects', 'list', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']'> rc=01486vm-test-run-scheduled-effects> buildbot # [   49.981289] twistd[1330]: 2026-06-07T06:20:40+0000 [-] releaseLocks(BuildbotEffectsCommand(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x7cc6005ecd70>, 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 0x7cc600645300>, logEnviron=False)): []1487vm-test-run-scheduled-effects> buildbot # [   49.995944] twistd[1330]: 2026-06-07T06:20:40+0000 [-]  step 'Evaluate effects' complete: success (None)1488vm-test-run-scheduled-effects> buildbot # [   50.012059] twistd[1330]: 2026-06-07T06:20:40+0000 [-] releaseLocks(BuildbotEffectsTrigger(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x7cc6005ecd70>, effects_scheduler='test-flake-run-effect', name='Buildbot effect', effects=[])): []1489vm-test-run-scheduled-effects> buildbot # [   50.021900] twistd[1330]: 2026-06-07T06:20:40+0000 [-]  step 'Buildbot effect' complete: success (None)1490vm-test-run-scheduled-effects> buildbot # [   50.036091] twistd[1330]: 2026-06-07T06:20:40+0000 [-] <RemoteShellCommand '['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']'>: RemoteCommand.run [14]1491vm-test-run-scheduled-effects> buildbot # [   50.041410] twistd[1330]: 2026-06-07T06:20:40+0000 [-] command '['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']' in dir 'build'1492vm-test-run-scheduled-effects> buildbot # [   50.047603] twistd[1331]: 2026-06-07T06:20:40+0000 [Broker,client] (command 14): startCommand:shell1493vm-test-run-scheduled-effects> buildbot # [   50.050154] twistd[1331]: 2026-06-07T06:20:40+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']): RunProcess._startCommand1494vm-test-run-scheduled-effects> buildbot # [   50.055049] twistd[1331]: 2026-06-07T06:20:40+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):  buildbot-effects list-schedules --rev 22d1cc8fa14a383dad519b0a3f3ad8d86767af47 --branch master --repo test-flake1495vm-test-run-scheduled-effects> buildbot # [   50.063094] twistd[1331]: 2026-06-07T06:20:40+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):   in dir /var/lib/buildbot-worker/worker-000/test-flake_nix-eval/build (timeout 1200 secs)1496vm-test-run-scheduled-effects> buildbot # [   50.068763] twistd[1331]: 2026-06-07T06:20:40+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):   watching logfiles {}1497vm-test-run-scheduled-effects> buildbot # [   50.073279] twistd[1331]: 2026-06-07T06:20:40+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):   argv: [b'buildbot-effects', b'list-schedules', b'--rev', b'22d1cc8fa14a383dad519b0a3f3ad8d86767af47', b'--branch', b'master', b'--repo', b'test-flake']1498vm-test-run-scheduled-effects> buildbot # [   50.080070] twistd[1331]: 2026-06-07T06:20:40+0000 [Broker,client] (command ['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']):   using PTY: False1499vm-test-run-scheduled-effects> buildbot # [   50.429989] nix-daemon[1607]: accepted connection from pid 1628, user buildbot-worker1500vm-test-run-scheduled-effects> buildbot # [   50.463421] twistd[1331]: 2026-06-07T06:20:40+0000 [-] (command ['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']): command finished with signal None, exit code 0, elapsedTime: 0.4007351501vm-test-run-scheduled-effects> buildbot # [   50.469236] twistd[1331]: 2026-06-07T06:20:40+0000 [-] (command 14): ProtocolCommandBase.command_complete (success) <buildbot_worker.commands.shell.WorkerShellCommand object at 0x730f1f404850>1502vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builds1503vm-test-run-scheduled-effects> buildbot # [   50.476077] twistd[1330]: 2026-06-07T06:20:40+0000 [Broker,0,127.0.0.1] <RemoteShellCommand '['buildbot-effects', 'list-schedules', '--rev', '22d1cc8fa14a383dad519b0a3f3ad8d86767af47', '--branch', 'master', '--repo', 'test-flake']'> rc=01504vm-test-run-scheduled-effects> buildbot # [   50.535742] twistd[1330]: 2026-06-07T06:20:40+0000 [-] releaseLocks(ScheduledEffectsEvaluateCommand(project=<buildbot_nix.pull_based.project.PullBasedProject object at 0x7cc6005ecd70>, 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 0x7cc6006454e0>, hideStepIf=<function nix_eval_config.<locals>.<lambda> at 0x7cc600645580>, logEnviron=False)): []1505vm-test-run-scheduled-effects> buildbot # [   50.557604] twistd[1330]: 2026-06-07T06:20:40+0000 [-]  step 'Evaluate scheduled effects' complete: success (None)1506vm-test-run-scheduled-effects> buildbot # [   50.561343] twistd[1330]: 2026-06-07T06:20:40+0000 [-]  <Build test-flake/nix-eval number:1 results:success>: build finished1507vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1508vm-test-run-scheduled-effects> buildbot #  [   50.584454] twistd[1330]: 2026-06-07T06:20:40+0000 [-] releaseLocks(<Worker 'local-worker-000'>): []1509vm-test-run-scheduled-effects> buildbot #                                 Dload  Upload  Total   Spent   Left   Speed1510vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100    411 100    411   0      0   3096      0                              0100    411 100    411   0      0   2676      0                              0100    411 100    411   0      0   2409      0                              01511vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builds, in 0.28 seconds)1512vm-test-run-scheduled-effects> (finished: subtest: Wait for nix-eval build to complete, in 17.76 seconds)1513vm-test-run-scheduled-effects> subtest: Schedule cache is created1514vm-test-run-scheduled-effects> buildbot: waiting for success: test -f /var/lib/buildbot/scheduled-effects-cache/test-flake-schedules.json1515vm-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)1516vm-test-run-scheduled-effects> buildbot: must succeed: cat /var/lib/buildbot/scheduled-effects-cache/test-flake-schedules.json1517vm-test-run-scheduled-effects> buildbot: (finished: must succeed: cat /var/lib/buildbot/scheduled-effects-cache/test-flake-schedules.json, in 0.04 seconds)1518vm-test-run-scheduled-effects> (finished: subtest: Schedule cache is created, in 0.06 seconds)1519vm-test-run-scheduled-effects> subtest: Nightly schedulers are created1520vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1521vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1522vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1523vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   3793 100   3793   0      0  42995      0                              0100   3793 100   3793   0      0  38512      0                              0100   3793 100   3793   0      0  34975      0                              01524vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.17 seconds)1525vm-test-run-scheduled-effects> buildbot # [   51.021611] sshd-session[1654]: Accepted publickey for root from ::1 port 54004 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81526vm-test-run-scheduled-effects> buildbot # [   51.038189] sshd-session[1654]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1527vm-test-run-scheduled-effects> buildbot # [   51.051075] systemd-logind[896]: New session '7' of user 'root' with class 'user' and type 'tty'.1528vm-test-run-scheduled-effects> buildbot # [   51.054362] systemd[1]: Started Session 7 of User root.1529vm-test-run-scheduled-effects> buildbot # [   51.096218] sshd-session[1665]: Received disconnect from ::1 port 54004:11: disconnected by user1530vm-test-run-scheduled-effects> buildbot # [   51.099310] sshd-session[1665]: Disconnected from user root ::1 port 540041531vm-test-run-scheduled-effects> buildbot # [   51.102174] sshd-session[1654]: pam_unix(sshd:session): session closed for user root1532vm-test-run-scheduled-effects> buildbot # [   51.112367] systemd[1]: session-7.scope: Deactivated successfully.1533vm-test-run-scheduled-effects> buildbot # [   51.118944] systemd-logind[896]: Session 7 logged out. Waiting for processes to exit.1534vm-test-run-scheduled-effects> buildbot # [   51.123749] systemd-logind[896]: Removed session 7.1535vm-test-run-scheduled-effects> buildbot # [   51.322493] sshd-session[1670]: Accepted publickey for root from ::1 port 54006 ssh2: ED25519 SHA256:9bQN408SyytfaJe89BgemJ/ksIKTwmKJks3tp9SgYW81536vm-test-run-scheduled-effects> buildbot # [   51.343735] sshd-session[1670]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)1537vm-test-run-scheduled-effects> buildbot # [   51.354630] systemd-logind[896]: New session '8' of user 'root' with class 'user' and type 'tty'.1538vm-test-run-scheduled-effects> buildbot # [   51.360535] systemd[1]: Started Session 8 of User root.1539vm-test-run-scheduled-effects> buildbot # [   51.410506] sshd-session[1673]: Received disconnect from ::1 port 54006:11: disconnected by user1540vm-test-run-scheduled-effects> buildbot # [   51.412738] sshd-session[1673]: Disconnected from user root ::1 port 540061541vm-test-run-scheduled-effects> buildbot # [   51.414759] sshd-session[1670]: pam_unix(sshd:session): session closed for user root1542vm-test-run-scheduled-effects> buildbot # [   51.423680] systemd[1]: session-8.scope: Deactivated successfully.1543vm-test-run-scheduled-effects> buildbot # [   51.429210] systemd-logind[896]: Session 8 logged out. Waiting for processes to exit.1544vm-test-run-scheduled-effects> buildbot # [   51.433837] systemd-logind[896]: Removed session 8.1545vm-test-run-scheduled-effects> buildbot # [   51.442699] twistd[1330]: 2026-06-07T06:20:41+0000 [-] gitpoller: processing changes from "ssh://root@localhost/srv/repos/test-flake.git"1546vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1547vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1548vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1549vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   3793 100   3793   0      0  39221      0                              0100   3793 100   3793   0      0  35438      0                              0100   3793 100   3793   0      0  32439      0                              01550vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.21 seconds)1551vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1552vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1553vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1554vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   3793 100   3793   0      0  38309      0                              0100   3793 100   3793   0      0  34657      0                              0100   3793 100   3793   0      0  31772      0                              01555vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.21 seconds)1556vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1557vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1558vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1559vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   3793 100   3793   0      0  37061      0                              0100   3793 100   3793   0      0  33657      0                              0100   3793 100   3793   0      0  30940      0                              01560vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.21 seconds)1561vm-test-run-scheduled-effects> buildbot # [   55.529337] twistd[1330]: 2026-06-07T06:20:45+0000 [buildbot_nix.nix_eval#info] Triggering reconfig due to schedule changes in test-flake1562vm-test-run-scheduled-effects> buildbot # [   55.532719] twistd[1330]: 2026-06-07T06:20:45+0000 [-] beginning configuration update1563vm-test-run-scheduled-effects> buildbot # [   55.535276] twistd[1330]: 2026-06-07T06:20:45+0000 [-] Loading configuration from '/nix/store/lrw01m59h52qsb3jnqd1wm6qfaj4z4sv-master.cfg'1564vm-test-run-scheduled-effects> buildbot # [   55.560735] twistd[1330]: 2026-06-07T06:20:45+0000 [-] gitpoller: using workdir '/var/lib/buildbot/master/gitpoller-work'1565vm-test-run-scheduled-effects> buildbot # [   55.568639] twistd[1330]: 2026-06-07T06:20:45+0000 [-] adding 1 new schedulers, removing 01566vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1567vm-test-run-scheduled-effects> buildbot # [   55.700236] twistd[1330]: 2026-06-07T06:20:46+0000 [-] configuration update complete (took 0.169 seconds)1568vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1569vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1570vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   4079 100   4079   0      0  40570      0                              0100   4079 100   4079   0      0  36680      0                              0100   4079 100   4079   0      0  33664      0                              01571vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.23 seconds)1572vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/schedulers1573vm-test-run-scheduled-effects> buildbot #   % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current1574vm-test-run-scheduled-effects> buildbot #                                  Dload  Upload  Total   Spent   Left   Speed1575vm-test-run-scheduled-effects> buildbot #   0      0   0      0   0      0      0      0                              0100   4079 100   4079   0      0  40402      0                              0100   4079 100   4079   0      0  36651      0                              0100   4079 100   4079   0      0  33629      0                              01576vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/schedulers, in 0.18 seconds)1577vm-test-run-scheduled-effects> (finished: subtest: Nightly schedulers are created, in 5.22 seconds)1578vm-test-run-scheduled-effects> subtest: Scheduled effect builder exists1579vm-test-run-scheduled-effects> buildbot: must succeed: curl --fail http://localhost:8010/api/v2/builders1580vm-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   2371 100   2371   0      0  59571      0                              0100   2371 100   2371   0      0  47435      0                              0100   2371 100   2371   0      0  39576      0                              01583vm-test-run-scheduled-effects> buildbot: (finished: must succeed: curl --fail http://localhost:8010/api/v2/builders, in 0.12 seconds)1584vm-test-run-scheduled-effects> (finished: subtest: Scheduled effect builder exists, in 0.12 seconds)1585vm-test-run-scheduled-effects> (finished: run the VM test script, in 57.48 seconds)1586vm-test-run-scheduled-effects> test script finished in 57.53s1587vm-test-run-scheduled-effects> cleanup1588vm-test-run-scheduled-effects> kill QemuMachine (pid 12)1589vm-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)1590vm-test-run-scheduled-effects> (finished: cleanup, in 0.22 seconds)15911592post-build step Upload coverage to codecov: ok1593Skipping codecov: project=nix-community/buildbot-nix attr=x86_64-linux.scheduled-effects