diff --git a/benchmarks/aft-search/slice-descriptors/land-flake-batch-9.json b/benchmarks/aft-search/slice-descriptors/land-flake-batch-9.json new file mode 100644 index 0000000000..3a0e5f4cf0 --- /dev/null +++ b/benchmarks/aft-search/slice-descriptors/land-flake-batch-9.json @@ -0,0 +1,12 @@ +{ + "slice_class": "non_ranking", + "targeted_mechanism": "none", + "kind": "harness", + "fixtures": [ + "harness-goldens" + ], + "slices": [ + "flake-batch-9" + ], + "note": "Test-only fix plus one INFO log line: the Windows PTY console round-trip test waits separately for PowerShell startup and for the round trip; bash_write logs the byte count it sent. No changed path matches RANKING_FENCE_PREFIXES." +} diff --git a/crates/aft/src/bash_background/registry.rs b/crates/aft/src/bash_background/registry.rs index b391f9572b..a9c438eb86 100644 --- a/crates/aft/src/bash_background/registry.rs +++ b/crates/aft/src/bash_background/registry.rs @@ -5664,6 +5664,10 @@ impl BgTaskRegistry { writer .flush() .map_err(|error| format!("failed to flush PTY writer: {error}"))?; + // Record that typed input reached the terminal, so a task that later + // seems to ignore its input can be told apart from one that never got + // it. Only the size is logged: the input can contain secrets. + crate::slog_info!("bash_write task={task_id} bytes={}", input.len()); Ok(input.len()) } diff --git a/crates/aft/src/gh_shim.rs b/crates/aft/src/gh_shim.rs index f1863b75e0..fa7df3fbb4 100644 --- a/crates/aft/src/gh_shim.rs +++ b/crates/aft/src/gh_shim.rs @@ -7867,6 +7867,13 @@ mod v22_tests; // use read as dead there; the module compiles in both profiles. #[cfg_attr(not(debug_assertions), allow(dead_code))] mod tests { + /// Deadline for tests that expect rung discovery to finish. The product + /// budget is 2 s; a loaded Windows runner has exceeded it, which turns the + /// answer into R1 (budget exhausted) and fails tests that are not about the + /// budget. Tests of the budget itself (expired deadlines, slow test + /// daemons, probe stages) keep `DISCOVERY_BUDGET` so they still time out. + const TEST_DISCOVERY_DEADLINE: Duration = Duration::from_secs(60); + #[cfg(unix)] #[test] fn supplemental_numeric_id_probe_does_not_accept_an_expired_deadline() { @@ -8393,7 +8400,7 @@ mod tests { &paths, Path::new("/cwd"), 123, - std::time::Instant::now() + DISCOVERY_BUDGET, + std::time::Instant::now() + TEST_DISCOVERY_DEADLINE, Some(&doc), ); assert_eq!(record.record.rung, Rung::R1); @@ -8422,7 +8429,7 @@ mod tests { &paths, Path::new("/cwd"), 1, - std::time::Instant::now() + DISCOVERY_BUDGET, + std::time::Instant::now() + TEST_DISCOVERY_DEADLINE, Some(&doc), ); assert_eq!(record.record.rung, Rung::R1); @@ -8445,7 +8452,7 @@ mod tests { &paths, Path::new("/cwd"), 1, - std::time::Instant::now() + DISCOVERY_BUDGET, + std::time::Instant::now() + TEST_DISCOVERY_DEADLINE, Some("{}"), ); assert_eq!(record.record.rung, Rung::R1); @@ -10615,7 +10622,7 @@ mod tests { "subc": { "connection_file": connection_file } }) .to_string(); - let future_deadline = || std::time::Instant::now() + DISCOVERY_BUDGET; + let future_deadline = || std::time::Instant::now() + TEST_DISCOVERY_DEADLINE; let r1_cases = [ ( R1Reason::DisabledByConfig, @@ -15270,7 +15277,7 @@ INHERITED FLAGS &paths, &project, TEST_NOW, - Instant::now() + DISCOVERY_BUDGET, + Instant::now() + TEST_DISCOVERY_DEADLINE, Some(&doc), ); let same_repo = repo == Some("cortexkit/motor"); @@ -15346,7 +15353,7 @@ INHERITED FLAGS &paths, &unbound, now, - Instant::now() + DISCOVERY_BUDGET, + Instant::now() + TEST_DISCOVERY_DEADLINE, Some(&doc), ); assert_eq!(unbound_determination.record.rung, Rung::R2); @@ -15370,7 +15377,7 @@ INHERITED FLAGS &target, &bound, now + 1, - Instant::now() + DISCOVERY_BUDGET, + Instant::now() + TEST_DISCOVERY_DEADLINE, Some(&doc), ); assert!( diff --git a/crates/aft/tests/integration/bash_exit_status_test.rs b/crates/aft/tests/integration/bash_exit_status_test.rs index 6b39bd23fe..0fef2f3a89 100644 --- a/crates/aft/tests/integration/bash_exit_status_test.rs +++ b/crates/aft/tests/integration/bash_exit_status_test.rs @@ -224,8 +224,19 @@ fn bash_waiter_kill_terminates_shell_and_descendants() { } } +/// Runs `command` in a PowerShell PTY task, types `input` once after the task +/// prints `ready`, and checks the exit code and output. +/// +/// The wait has two separate budgets. PowerShell startup under a busy test +/// runner can take most of a single shared budget (it was seen taking 9-17 s +/// on a 4-CPU Windows runner with 16 tasks in parallel), which used to leave +/// almost no time for the read, echo and exit after a late `ready` and made +/// a slow start look like lost input. Failure messages name the phase and +/// the moments `ready` was seen and the write returned. #[cfg(windows)] fn pty_console_round_trip(command: &str, input: &str, expected_code: i32, expected_output: &str) { + const STARTUP_BUDGET: Duration = Duration::from_secs(120); + const ROUND_TRIP_BUDGET: Duration = Duration::from_secs(30); let project = tempfile::tempdir().unwrap(); let mut aft = AftProcess::spawn(); let configured = aft.send(&json!({ @@ -239,27 +250,39 @@ fn pty_console_round_trip(command: &str, input: &str, expected_code: i32, expect }).to_string()); assert_eq!(spawned["success"], true, "{spawned}"); let task_id = &spawned["task_id"]; - let deadline = Instant::now() + Duration::from_secs(30); - let mut sent = false; + let started = Instant::now(); + let mut deadline = started + STARTUP_BUDGET; + // Moments since spawn when `ready` was first seen and when the single + // bash_write returned; `Some` on the latter also means the input was sent. + let mut ready_seen = None; + let mut write_returned = None; loop { let status = aft.send(&json!({ "id":"stdin-status", "command":"bash_status", "params":{"task_id":task_id,"output_mode":"raw"}, }).to_string()); assert_eq!(status["success"], true, "{status}"); let output = status["pty_raw"].as_str().unwrap_or_default(); - if !sent && output.contains("ready") { + if write_returned.is_none() && output.contains("ready") { + ready_seen = Some(started.elapsed()); let written = aft.send(&json!({ "id":"stdin-write", "command":"bash_write", "params":{"task_id":task_id,"input":input}, }).to_string()); assert_eq!(written["success"], true, "{written}"); - sent = true; + write_returned = Some(started.elapsed()); + deadline = Instant::now() + ROUND_TRIP_BUDGET; } + let timing = format!("ready_seen={ready_seen:?} write_returned={write_returned:?}"); if status["status"] != "running" { - assert_eq!(status["exit_code"], expected_code, "{status}"); - assert!(output.contains(expected_output), "{status}"); + assert_eq!(status["exit_code"], expected_code, "{timing} {status}"); + assert!(output.contains(expected_output), "{timing} {status}"); break; } - assert!(Instant::now() < deadline, "{status}"); + let phase = if write_returned.is_some() { + "no exit within the round-trip budget after the write" + } else { + "no `ready` within the startup budget" + }; + assert!(Instant::now() < deadline, "{phase}: {timing} {status}"); std::thread::sleep(Duration::from_millis(50)); } assert!(aft.shutdown().success());