sched(508): the x86 boot thread is not preempted away during its disk-completion wait

docs/planning/green-program/block/serials/508/baseline/markers.txt

@@ -0,0 +1,5 @@
+serial_kernel.txt:15120: [ INFO] kernel::test_exec: === MULTIPLE CONCURRENT PROCESSES TEST ===
+serial_kernel.txt:17675: [ INFO] kernel::syscall::handlers: TEST_TALLY: exited=110 nonzero=0 failed=[]
+serial_kernel.txt:17682: [ INFO] kernel::syscall::handlers: 🏁 TEST RUNNER: All tests passed - you can exit QEMU now 🏁
+serial_user.txt:1085: [BOOT_DISK_WAIT_ORACLE:x86:switched_away=367:tests_completed=0:FAIL]
+serial_user.txt:1086: [BOOT_DISK_WAIT_TRACE:x86:switch_preempt=0]

docs/planning/green-program/block/serials/508/landing/aarch64-build.log

@@ -0,0 +1,49 @@
+REVISION=327b42f4ab2ce221a575c226229addb8ebe7a3fc kernel source unchanged by pending fixture replacement
+    Updating git repository `https://github.com/rust-osdev/bootloader.git`
+    Updating crates.io index
+     Locking 154 packages to latest compatible versions
+      Adding aarch64-cpu v9.4.0 (available: v11.2.0)
+      Adding acpi v5.2.0 (available: v6.1.1)
+      Adding az v1.2.1 (available: v1.3.0)
+      Adding pic8259 v0.10.4 (available: v0.11.0)
+      Adding spin v0.9.9 (available: v0.12.3)
+      Adding tock-registers v0.8.1 (available: v0.10.1)
+      Adding uart_16550 v0.3.2 (available: v0.8.0)
+      Adding uefi v0.33.0 (available: v0.37.0)
+      Adding x86_64 v0.15.4 (available: v0.15.5)
+   Compiling compiler_builtins v0.1.160 (/Users/wrb/.rustup/toolchains/nightly-2025-06-24-aarch64-apple-darwin/lib/rustlib/src/rust/library/compiler-builtins/compiler-builtins)
+   Compiling core v0.0.0 (/Users/wrb/.rustup/toolchains/nightly-2025-06-24-aarch64-apple-darwin/lib/rustlib/src/rust/library/core)
+   Compiling autocfg v1.5.1
+   Compiling az v1.2.1
+   Compiling crossbeam-utils v0.8.23
+   Compiling bootloader_api v0.11.13 (https://github.com/rust-osdev/bootloader.git?rev=707db11201b19541b7cfef84037866ee03aa0927#707db112)
+   Compiling kernel v0.1.0 (/private/tmp/claude-501/-Users-wrb-fun-code-breenix/d69ffb9d-4539-4cf3-8a3d-a872ff7c830b/scratchpad/b508/wt/kernel)
+   Compiling num-traits v0.2.19
+   Compiling alloc v0.0.0 (/Users/wrb/.rustup/toolchains/nightly-2025-06-24-aarch64-apple-darwin/lib/rustlib/src/rust/library/alloc)
+   Compiling scopeguard v1.2.0
+   Compiling byteorder v1.5.0
+   Compiling futures-task v0.3.34
+   Compiling micromath v2.1.0
+   Compiling pin-project-lite v0.2.17
+   Compiling futures-core v0.3.34
+   Compiling conquer-util v0.3.0
+   Compiling tock-registers v0.8.1
+   Compiling slab v0.4.12
+   Compiling noto-sans-mono-bitmap v0.3.2
+   Compiling rlibc v1.0.0
+   Compiling log v0.4.34
+   Compiling lock_api v0.4.14
+   Compiling conquer-once v0.4.0
+   Compiling aarch64-cpu v9.4.0
+   Compiling futures-util v0.3.34
+   Compiling spinning_top v0.2.5
+   Compiling spin v0.9.9
+   Compiling linked_list_allocator v0.10.6
+   Compiling crossbeam-queue v0.3.14
+   Compiling float-cmp v0.9.0
+   Compiling embedded-graphics-core v0.4.1
+   Compiling embedded-graphics v0.8.2
+    Finished `release` profile [optimized] target(s) in 21.77s
+warning: the following packages contain code that will be rejected by a future version of Rust: core v0.0.0 (/Users/wrb/.rustup/toolchains/nightly-2025-06-24-aarch64-apple-darwin/lib/rustlib/src/rust/library/core)
+note: to see what the problems were, use the option `--future-incompat-report`, or run `cargo report future-incompatibilities --id 1`
+EXIT=0

docs/planning/green-program/block/serials/508/landing/aarch64-strict.log

@@ -0,0 +1,127 @@
+REVISION=6cff8cf8c43adeeccd8d6088a5c42af70091233e
+[GATE_SUITE:stem=aarch64_testing_profile_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=block_request_lifetime_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=blocking_fd_eagain_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=boot_disk_wait_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=bssh_auth_close_structure:attempt=1:timeout_s=300:wall_s=2:exit=0]
+[GATE_SUITE:stem=capture_bxcap_schema_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=capture_path_lock_free_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=console_read_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=context_restore_structure:attempt=1:timeout_s=300:wall_s=58:exit=0]
+[GATE_SUITE:stem=coreproof_component_h_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=coreproof_coverage_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=coreproof_mutation_register_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=coreproof_sites_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=critical_path_logging_census_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=ctx_diag_ring_sample_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=degenerate_transfer_fd_validation_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=dispatch_fact_census_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=dispatch_path_lock_free_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=dispatch_strand_census_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=dma_and_log_sink_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=entry_point_df_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=exec_lock_order_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=exit_tally_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=ext2_disk_size_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=ext2_lock_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=fcntl_pm_contention_gate_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=fork_lock_order_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=gate_boot_facts_pipefail_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=gate_boot_facts_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=gate_capture_drain_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=gate_qmp_backstop_structure:attempt=1:timeout_s=300:wall_s=6:exit=0]
+[GATE_SUITE:stem=gate_structure_preflight_wiring_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=green_program_envelope_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=launcher_smoke_xhci_evidence_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=lockup_capture_guard_structure:attempt=1:timeout_s=300:wall_s=2:exit=0]
+[GATE_SUITE:stem=loopback_pump_structure:attempt=1:timeout_s=300:wall_s=4:exit=0]
+[GATE_SUITE:stem=masked_binary_load_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=mmap_floor_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=net_lock_structure:attempt=1:timeout_s=300:wall_s=2:exit=0]
+[GATE_SUITE:stem=parallels_capture_structure:attempt=1:timeout_s=300:wall_s=2:exit=0]
+[GATE_SUITE:stem=parallels_kill_by_name_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=pipe_fifo_blocking_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=poll_tcp_gate_wiring_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=preempt_bracket_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=qemu_host_lock_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=qemu_kill_by_name_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=ring_span_report_site_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=ring_span_unfiltered_report_site_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=run_inspector_import_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=serial_line_atomicity_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=signal_eintr_predicate_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=softirq_deferral_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=strand_handoff_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=structure_preflight_parallel_structure:attempt=1:timeout_s=300:wall_s=6:exit=0]
+[GATE_SUITE:stem=syscall_return_register_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=teardown_rustfmt_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=teardown_structure:attempt=1:timeout_s=300:wall_s=19:exit=0]
+[GATE_SUITE:stem=terminal_edge_capture_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=timer_wake_dispatch_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=trace_ring_depth_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=tracing_provider_gate_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=ttbr0_shadow_reconciliation_structure:attempt=1:timeout_s=300:wall_s=18:exit=0]
+[GATE_SUITE:stem=tty_irq_fg_structure:attempt=1:timeout_s=300:wall_s=2:exit=0]
+[GATE_SUITE:stem=tty_irq_pm_structure:attempt=1:timeout_s=300:wall_s=2:exit=0]
+[GATE_SUITE:stem=tty_oracle_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=udp_ports_lock_irq_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=udp_socket_lock_irq_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=unix_stream_blocking_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=x86_boot_tests_profile_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_SUITE:stem=x86_smp_enum_structure:attempt=1:timeout_s=300:wall_s=0:exit=0]
+[GATE_SUITE:stem=xhci_wait_irq_order_structure:attempt=1:timeout_s=300:wall_s=1:exit=0]
+[GATE_PREFLIGHT:structure_suites=71/71:critical_path_lines=244:pinned=105]
+Guard: kernel FP/SIMD instruction check
+  ELF:       /private/tmp/claude-501/-Users-wrb-fun-code-breenix/d69ffb9d-4539-4cf3-8a3d-a872ff7c830b/scratchpad/b508/wt/target/aarch64-breenix-kernel/release/kernel-aarch64
+  objdump:   /Users/wrb/.rustup/toolchains/nightly-2025-06-24-aarch64-apple-darwin/lib/rustlib/aarch64-apple-darwin/bin/llvm-objdump
+  allowlist: /private/tmp/claude-501/-Users-wrb-fun-code-breenix/d69ffb9d-4539-4cf3-8a3d-a872ff7c830b/scratchpad/b508/wt/scripts/kernel-neon-allowlist.txt
+PASS: 0 FP/SIMD load/store instructions in kernel .text (allowlisted & suppressed: 0).
+Guard: aarch64 soft-lockup report allocation check (failure-capture PR-7)
+  ELF:      /private/tmp/claude-501/-Users-wrb-fun-code-breenix/d69ffb9d-4539-4cf3-8a3d-a872ff7c830b/scratchpad/b508/wt/target/aarch64-breenix-kernel/release/kernel-aarch64
+  sha256:   f66a1369eafc1ad85d937a52ece8ade75c450b5e913542ec1a2c9b448f6044cb
+  objdump:  /Users/wrb/.rustup/toolchains/nightly-2025-06-24-aarch64-apple-darwin/lib/rustlib/aarch64-apple-darwin/bin/llvm-objdump
+  root:     dump_lockup_state (its own symbols and every reachable callee)
+  roots:           1
+    _ZN6kernel9arch_impl7aarch6415timer_interrupt17dump_lockup_state17h61ecf85f7d566472E
+  reachable funcs: 18
+  call edges:      32
+PASS: 0 allocation sinks reachable from 1 root symbol(s).
+PASS: no allocation is reachable from dump_lockup_state in this ELF.
+=========================================
+ARM64 Strict Boot Test
+=========================================
+Kernel: /private/tmp/claude-501/-Users-wrb-fun-code-breenix/d69ffb9d-4539-4cf3-8a3d-a872ff7c830b/scratchpad/b508/wt/target/aarch64-breenix-kernel/release/kernel-aarch64
+ext2 disk: /private/tmp/claude-501/-Users-wrb-fun-code-breenix/d69ffb9d-4539-4cf3-8a3d-a872ff7c830b/scratchpad/b508/wt/target/ext2-aarch64.img
+Iterations: 1
+Requirement: 100% success rate (all 1 must pass)
+
+Running tests...
+
+QEMU HOST LOCK: host qemu-system-aarch64 count before acquire: 0
+qemu-system-aarch64: terminating on signal 15
+  [FAIL] Boot 1: T2T3T4T5[SOFTIRQ_DEFERRAL_ORACLE:arch=aarch64:cpu=1:budget_ticks=250:wait_ticks=2:wait_ns=2308000:dispatches=5:iterations=25:verdict=ok]
+BSSH publickey oracle missing, duplicated, or failed (1398 lines); serial: /private/tmp/claude-501/-Users-wrb-fun-code-breenix/d69ffb9d-4539-4cf3-8a3d-a872ff7c830b/scratchpad/b508/wt/.gate-tmp/breenix_aarch64_strict_failures/20260908T143833Z-boot1.txt
+  [GATE_BOOT_FACTS:boot=1:host_ms=1788878211571-1788878313147:qemu_at_start=0:load_at_start=9.23:qemu_at_end=0:load_at_end=4.73:qemu_cpu_s=NA:guest_uptime_ms=89234:ended_by=hard_timeout]
+  [CAPTURE_DRAIN:capture=absent:seq=-:edge=-:cpu=-:records=-:drain_ms=300]
+  [CAPTURE_DRAIN_EVENTS:last_events=none]
+  [QMP_DUMP:capture=partial:reason=qmp_socket_missing:core=-:decoded_events=-:dump_ms=14]
+
+=========================================
+RESULTS
+=========================================
+Total iterations: 1
+Successes: 0
+Failures: 1
+Inconclusive (host starvation): 0
+Success rate: 0%
+Duration: 103s
+
+Failed iterations: 1
+
+=========================================
+FAIL: Only 0/1 boots succeeded
+=========================================
+
+This indicates a regression or timing bug that needs investigation.
+Serial output from failed boots can be found in /private/tmp/claude-501/-Users-wrb-fun-code-breenix/d69ffb9d-4539-4cf3-8a3d-a872ff7c830b/scratchpad/b508/wt/.gate-tmp/breenix_aarch64_strict_N/
+EXIT=1

docs/planning/green-program/block/serials/508/landing/source-citations.txt

@@ -0,0 +1,43 @@
+REVISION=74a57ab9a5c507be6ce8c6c20c662884d80590df
+kernel/src/task/completion.rs:147: fn wait_idle_completion(completion: &Completion, expected_token: u32, timeout_ns: u64) -> bool {
+kernel/src/task/completion.rs:198: pub fn waiter_tid(&self) -> u64 {
+kernel/src/task/completion.rs:214: pub fn wait_timeout(&self, expected_token: u32, timeout_ns: u64) -> Result<bool, i32> {
+kernel/src/task/completion.rs:222: pub fn wait_timeout_uninterruptible(
+kernel/src/task/completion.rs:230: fn wait_timeout_inner(
+kernel/src/task/completion.rs:390: Cpu::halt_with_interrupts();
+kernel/src/per_cpu.rs:38: // unpaired enable wrapped preempt_count to 0xFFFFFFFF and can_schedule()'s
+kernel/src/per_cpu.rs:39: // `preempt_count == 0` arms - ordinary timer preemption and yield-driven
+kernel/src/per_cpu.rs:72: pub preempt_count: u32,
+kernel/src/per_cpu.rs:169: // Linux-style preempt_count bit layout constants
+kernel/src/per_cpu.rs:233: offset_of!(PerCpuData, preempt_count) == PERCPU_PREEMPT_COUNT_OFFSET,
+kernel/src/per_cpu.rs:292: "preempt_count must be 4-byte aligned"
+kernel/src/per_cpu.rs:328: preempt_count: 0,
+kernel/src/per_cpu.rs:406: // Verify preempt_count read/write cycle
+kernel/src/per_cpu.rs:407: let initial_preempt = hal_percpu::X86PerCpu::preempt_count();
+kernel/src/per_cpu.rs:409: let after_disable = hal_percpu::X86PerCpu::preempt_count();
+kernel/src/per_cpu.rs:418: let after_enable = hal_percpu::X86PerCpu::preempt_count();
+kernel/src/per_cpu.rs:430: "Per-CPU data marked as initialized - preempt_count functions now use per-CPU storage"
+kernel/src/per_cpu.rs:689: let count_before = hal_percpu::X86PerCpu::preempt_count();
+kernel/src/per_cpu.rs:692: "irq_exit called but HARDIRQ count is already 0 (preempt_count={:#x})",
+kernel/src/per_cpu.rs:716: // Use HAL to read current preempt_count
+kernel/src/per_cpu.rs:718: let new_count = hal_percpu::X86PerCpu::preempt_count();
+kernel/src/per_cpu.rs:753: let count_before = hal_percpu::X86PerCpu::preempt_count();
+kernel/src/per_cpu.rs:756: "nmi_exit called but NMI count is already 0 (preempt_count={:#x})",
+kernel/src/per_cpu.rs:799: let count_before = hal_percpu::X86PerCpu::preempt_count();
+kernel/src/per_cpu.rs:802: "bh_enable called but bottom halves are not disabled (preempt_count={:#x})",
+kernel/src/per_cpu.rs:820: let count_before = hal_percpu::X86PerCpu::preempt_count();
+kernel/src/per_cpu.rs:823: "softirq_exit called but SOFTIRQ count is already 0 (preempt_count={:#x})",
+kernel/src/per_cpu.rs:958: // do not need to be: preempt_count is per-CPU, the PREEMPT field is moved
+kernel/src/per_cpu.rs:963: if hal_percpu::X86PerCpu::preempt_count() & PREEMPT_MASK == 0 {
+kernel/src/per_cpu.rs:990: pub fn preempt_count() -> u32 {
+kernel/src/per_cpu.rs:993: "preempt_count called before per-CPU initialization"
+kernel/src/per_cpu.rs:998: hal_percpu::X86PerCpu::preempt_count()
+kernel/src/per_cpu.rs:1001: /// Clear PREEMPT_ACTIVE bit (bit 28) from preempt_count
+kernel/src/per_cpu.rs:1365: /// Check if we can schedule (preempt_count == 0 and returning to userspace)
+kernel/src/per_cpu.rs:1366: pub fn can_schedule(saved_cs: u64) -> bool {
+kernel/src/per_cpu.rs:1367: let current_preempt = preempt_count();
+kernel/src/interrupts/context_switch.rs:367: switch_to_thread(
+kernel/src/interrupts/context_switch.rs:375: // Observe the resolved dispatch, after TLS/first-entry rollback can
+kernel/src/interrupts/context_switch.rs:655: fn switch_to_thread(
+kernel/src/boot/disk_wait_oracle.rs:34: "[BOOT_DISK_WAIT_ORACLE:x86:switched_away={}:tests_completed={}:{}]",
+kernel/src/main.rs:2084: serial_println!("[TEST_EXEC_BLOCK_COMPLETE:x86:calls=64]");