diff --git a/tests/e2e-cucumber/src/lib.rs b/tests/e2e-cucumber/src/lib.rs index 948ab404..7fccc569 100644 --- a/tests/e2e-cucumber/src/lib.rs +++ b/tests/e2e-cucumber/src/lib.rs @@ -47,6 +47,21 @@ pub fn lifecycle_binary_dir( Ok(rocm_dir) } +/// One labelled block of a diagnostic bundle. +/// +/// An empty body is marked `(empty)` rather than omitted, because "the CLI said +/// nothing" and "the harness lost the output" are different diagnoses and only +/// an explicit marker tells them apart. Shared by [`cli_failure_report`] and +/// [`serve_log::serve_attempt_report`] so every bundle reads the same way. +pub(crate) fn section(label: &str, body: &str) -> String { + let body = body.trim_end(); + if body.is_empty() { + format!("--- {label}: (empty) ---") + } else { + format!("--- {label} ---\n{body}") + } +} + /// Render everything known about a failed `rocm` invocation. /// /// Both streams are always shown, each labelled and each with an explicit @@ -58,15 +73,11 @@ pub fn lifecycle_binary_dir( /// stdout leaves a failed step undiagnosable: the panic reads `rocm serve /// failed:` followed by nothing at all, which is what EAI-8031 hit on the /// MI300X lane. The CLI reports its errors on stderr. +/// +/// Covers only a NON-ZERO exit. A `--managed` serve that exits 0 and then never +/// serves needs [`serve_log::serve_attempt_report`] instead — same streams, plus +/// the engine log and device state that are the only evidence in that case. pub fn cli_failure_report(args: &[&str], rc: i32, stdout: &str, stderr: &str) -> String { - fn section(label: &str, body: &str) -> String { - let body = body.trim_end(); - if body.is_empty() { - format!("--- {label}: (empty) ---") - } else { - format!("--- {label} ---\n{body}") - } - } format!( "`rocm {}` failed (rc={rc})\n{}\n{}", args.join(" "), diff --git a/tests/e2e-cucumber/src/serve_log.rs b/tests/e2e-cucumber/src/serve_log.rs index 47f03f86..bf0ff9d8 100644 --- a/tests/e2e-cucumber/src/serve_log.rs +++ b/tests/e2e-cucumber/src/serve_log.rs @@ -10,10 +10,41 @@ //! that failed to import) is written to the service log in a per-scenario temp //! directory that no report artifact captures. Quoting its tail into the failure //! is what makes such a stall diagnosable from CI output alone. +//! +//! `--managed` is what makes a stall this opaque: `rocm serve` returns as soon as +//! the supervisor is launched, so an engine that dies afterwards leaves a **zero** +//! exit code and no CLI-side error at all. Nothing about the failure is visible +//! from the exit status, which is why this module collects the evidence from +//! elsewhere — the CLI's own output, the engine's log, and the device state. +//! +//! Two things come out of here, and a failing serve step wants both: +//! +//! - [`service_log_tail`] — the last lines, quoted straight into the panic so the +//! job log explains itself without downloading anything; +//! - [`archive_service_log`] — the whole file, copied into the results directory +//! CI uploads, because the tail cannot show the engine's STARTUP banner (which +//! backend and device it chose), and the temp directory holding the original is +//! deleted with the scenario. + +use std::path::Path; /// How many trailing lines of a stalled service's log to quote in a failure. const DEFAULT_TAIL_LINES: usize = 40; +/// Subdirectory of the results directory that archived service logs land in. +/// Its parent is what CI uploads, so this path is also how the log is addressed +/// inside the artifact. +const ARCHIVE_SUBDIR: &str = "service-logs"; + +/// Cap on one archived service log. +/// +/// A runaway engine log — a stalled download's progress bars, a crash loop — +/// must not inflate the CI artifact. Past the cap the head and tail are kept and +/// the middle elided: llama.cpp and vLLM announce the backend and device they +/// selected in their FIRST lines and fail in their LAST, and it takes both halves +/// to tell "picked the wrong backend" apart from "died loading the weights". +const MAX_ARCHIVED_LOG_BYTES: u64 = 4 * 1024 * 1024; + /// The `log_path:` a `rocm serve --managed` plan reports for the service it /// launched, if the output carries one. fn parse_log_path(serve_stdout: &str) -> Option<&str> { @@ -57,9 +88,177 @@ pub fn service_log_tail(serve_stdout: &str) -> String { } } +/// A filename-safe form of a scenario name: lowercase, non-alphanumerics folded +/// to single dashes. Only ever used to LABEL a file whose uniqueness comes from +/// the service id already in its name, so collisions here cost nothing. +fn slugify(name: &str) -> String { + let mut slug = String::with_capacity(name.len()); + for ch in name.chars() { + if ch.is_ascii_alphanumeric() { + slug.push(ch.to_ascii_lowercase()); + } else if !slug.ends_with('-') { + slug.push('-'); + } + } + let slug = slug.trim_matches('-'); + if slug.is_empty() { + "scenario".to_owned() + } else { + slug.to_owned() + } +} + +/// Read at most `max` bytes of `path` for archiving, plus a note describing any +/// elision. A file that fits is returned verbatim; a larger one is returned as +/// its head and tail with the middle skipped and the gap marked. +/// +/// Bounded by SEEKING rather than by reading the file and trimming it after, +/// because the input is an engine log that has already misbehaved: a crash loop +/// or a stuck progress bar can leave one arbitrarily large, and an allocation +/// failure ABORTS the process rather than unwinding — destroying the very report +/// this is collecting. Seeking keeps the cost fixed however big the log grows. +/// +/// The log may still be being written, so `len` is a snapshot: the head and tail +/// are always real, and only the elided count can be slightly stale. +fn read_clamped(path: &Path, max: u64) -> std::io::Result<(Vec, String)> { + use std::io::{Read as _, Seek as _, SeekFrom}; + + let mut file = std::fs::File::open(path)?; + let len = file.metadata()?.len(); + if len <= max { + let mut body = Vec::new(); + file.read_to_end(&mut body)?; + return Ok((body, String::new())); + } + // `len > max >= 2 * half`, so the two halves can never overlap. + let half = max / 2; + let mut head = vec![0u8; half as usize]; + file.read_exact(&mut head)?; + file.seek(SeekFrom::Start(len - half))?; + let mut tail = vec![0u8; half as usize]; + file.read_exact(&mut tail)?; + + let elided = len - 2 * half; + let marker = format!("\n\n<<< {elided} bytes elided by the E2E harness >>>\n\n"); + let mut body = head; + body.extend_from_slice(marker.as_bytes()); + body.extend_from_slice(&tail); + Ok((body, format!(" ({elided} bytes elided from the middle)"))) +} + +/// Copy the log written by the managed service `serve_stdout` launched into +/// `results_dir`, and say where it landed. +/// +/// The original lives in the scenario's isolated temp data dir and is deleted +/// with that `TempDir` when the scenario ends, while CI uploads only the results +/// directory — so today a run keeps nothing of the one file that holds the +/// engine's own account of itself. Copying it there is what lets the NEXT red +/// run be root-caused, instead of the run after that. +/// +/// Returns the archived path relative to `results_dir` (which is how it is +/// addressed inside the uploaded artifact), or a bracketed reason it could not +/// be archived. +/// +/// Never fails, for the same reason [`service_log_tail`] never fails: it only +/// ever runs while another failure is already being reported, and panicking here +/// would replace that report with a double panic. +#[must_use] +pub fn archive_service_log(serve_stdout: &str, results_dir: &Path, scenario: &str) -> String { + let Some(source) = parse_log_path(serve_stdout) else { + return "".to_owned(); + }; + let source = Path::new(source); + let (body, note) = match read_clamped(source, MAX_ARCHIVED_LOG_BYTES) { + Ok(read) => read, + Err(error) => { + return format!( + "", + source.display() + ); + } + }; + let dir = results_dir.join(ARCHIVE_SUBDIR); + if let Err(error) = std::fs::create_dir_all(&dir) { + return format!( + "", + dir.display() + ); + } + // The service id already makes the source name unique per launch; the + // scenario slug in front says which scenario owns it without opening it. + let name = format!( + "{}--{}", + slugify(scenario), + source + .file_name() + .and_then(|name| name.to_str()) + .unwrap_or("service.log") + ); + match std::fs::write(dir.join(&name), body) { + Ok(()) => format!("archived to {ARCHIVE_SUBDIR}/{name}{note}"), + Err(error) => format!( + "", + dir.join(&name).display() + ), + } +} + +/// Everything one `rocm serve --managed` attempt left behind, in the order a +/// reader needs it. +/// +/// Collected as a struct rather than passed positionally because the fields are +/// six interchangeable strings, and getting two of them the wrong way round +/// would silently mislabel the evidence in a report nobody can cross-check. +#[derive(Debug, Clone, Copy)] +pub struct ServeAttempt<'a> { + /// One line saying what went wrong, including the invocation and exit code. + /// The caller owns this because only it knows whether the serve failed + /// outright or exited 0 and then never served. + pub headline: &'a str, + /// What the device looked like before this attempt started (see the serve + /// steps' `ensure_serve_port_free`). An undrained GPU is a common cause of a + /// serve that never becomes ready, and is invisible from anything else here. + pub device_state: &'a str, + pub stdout: &'a str, + pub stderr: &'a str, + /// [`service_log_tail`], read BEFORE the service was stopped so it reflects + /// what the engine wrote on its own rather than what the stop provoked. + pub log_tail: &'a str, + /// [`archive_service_log`]'s account of where the full log was saved. + pub archived_log: &'a str, + /// How stopping this attempt's service went. A stop that found no record, or + /// failed, means the engine may still hold the port and the device — which + /// changes how every later failure in the run should be read. + pub stop_status: &'a str, +} + +/// Render one serve attempt's evidence as a failure message. +/// +/// Every section is always present and empty ones are marked, on the same +/// reasoning as [`crate::cli_failure_report`]: a silent engine and a harness that +/// dropped the output look identical otherwise, and they call for opposite next +/// steps. +#[must_use] +pub fn serve_attempt_report(attempt: &ServeAttempt<'_>) -> String { + use crate::section; + format!( + "{}\n{}\n{}\n{}\n{}\n{}\n{}", + attempt.headline, + section("device state", attempt.device_state), + section("stdout", attempt.stdout), + section("stderr", attempt.stderr), + section("service log (tail)", attempt.log_tail), + section("service log (full)", attempt.archived_log), + section("stop", attempt.stop_status), + ) +} + #[cfg(test)] mod tests { - use super::{parse_log_path, service_log_tail, tail_lines}; + use super::{ + MAX_ARCHIVED_LOG_BYTES, ServeAttempt, archive_service_log, parse_log_path, read_clamped, + serve_attempt_report, service_log_tail, slugify, tail_lines, + }; const SERVE_PLAN: &str = "\ serve plan @@ -151,4 +350,183 @@ managed service launched "unexpected message: {reported}" ); } + + /// Write a service log and return the serve stdout that points at it. + fn planted_log(dir: &std::path::Path, name: &str, body: &[u8]) -> String { + let path = dir.join(name); + std::fs::write(&path, body).expect("write log"); + format!("managed service launched\n log_path: {}\n", path.display()) + } + + /// The whole point: the file the scenario's `TempDir` is about to delete ends + /// up under the results directory CI uploads, byte for byte. + #[test] + fn the_full_log_is_copied_into_the_results_directory() { + let dir = tempfile::tempdir().expect("tempdir"); + let results = tempfile::tempdir().expect("tempdir"); + // A startup banner the 40-line tail could not have shown, plus the + // failure at the end — archiving has to preserve both. + let body = b"ggml_cuda_init: found 1 ROCm device\nload: failed to load model\n"; + let stdout = planted_log(dir.path(), "lemonade-qwen3-0-6b-1785145816856.log", body); + + let reported = + archive_service_log(&stdout, results.path(), "14 - A canonical HF checkpoint"); + + let expected_name = "14-a-canonical-hf-checkpoint--lemonade-qwen3-0-6b-1785145816856.log"; + assert_eq!( + reported, + format!("archived to service-logs/{expected_name}"), + "the report must name the path as it appears inside the artifact" + ); + let archived = results.path().join("service-logs").join(expected_name); + assert_eq!( + std::fs::read(&archived).expect("archived log"), + body, + "the archived copy must be the log verbatim" + ); + } + + /// Read a log of `body` under an explicit cap. The cap is a parameter so the + /// boundary can be probed with bytes instead of megabytes. + fn read_log(body: &[u8], max: u64) -> (Vec, String) { + let dir = tempfile::tempdir().expect("tempdir"); + let path = dir.path().join("service.log"); + std::fs::write(&path, body).expect("write log"); + read_clamped(&path, max).expect("read log") + } + + /// A runaway log is bounded, but never at the cost of the startup banner: + /// both ends survive and the gap says so. + #[test] + fn an_oversized_log_keeps_both_ends_and_marks_the_gap() { + // 26 bytes under a 10-byte cap: 5 from each end, 16 elided. + let body = b"HEAD-rocm-backend-selected"; + let (clamped, note) = read_log(body, 10); + + let text = String::from_utf8_lossy(&clamped); + assert!(text.starts_with("HEAD-"), "head lost: {text}"); + assert!(text.ends_with("ected"), "tail lost: {text}"); + assert!( + text.contains("<<< 16 bytes elided by the E2E harness >>>"), + "the elision must be stated, not silent: {text}" + ); + assert_eq!(note, " (16 bytes elided from the middle)"); + } + + /// The cap itself: at exactly the limit nothing may be dropped, and one byte + /// over must drop exactly that byte — the halves must never overlap and so + /// never duplicate content into the archive. + #[test] + fn the_cap_boundary_neither_over_nor_under_trims() { + let body = b"abcdefgh"; + + let (at_cap, note) = read_log(body, 8); + assert_eq!(at_cap, body, "a log exactly at the cap must be verbatim"); + assert!(note.is_empty(), "no elision note expected: {note}"); + + // One byte over: half = 3, so "abc" and "fgh" survive and "de" is the gap. + // Asserted whole, so an overlap (which would duplicate bytes) cannot pass. + let (over_cap, note) = read_log(body, 7); + assert_eq!( + String::from_utf8_lossy(&over_cap), + "abc\n\n<<< 2 bytes elided by the E2E harness >>>\n\nfgh" + ); + assert_eq!(note, " (2 bytes elided from the middle)"); + } + + /// Reading is bounded by seeking, not by loading the log and trimming it, so + /// a log far larger than the cap costs no more than a log at the cap. + #[test] + fn a_log_far_over_the_cap_is_still_read_in_bounded_space() { + let body = vec![b'x'; 1024]; + let (clamped, note) = read_log(&body, 16); + assert_eq!(clamped.len(), 16 + note_marker_len(1008)); + assert_eq!(note, " (1008 bytes elided from the middle)"); + } + + fn note_marker_len(elided: u64) -> usize { + format!("\n\n<<< {elided} bytes elided by the E2E harness >>>\n\n").len() + } + + #[test] + fn every_unarchivable_case_explains_itself_instead_of_failing() { + let results = tempfile::tempdir().expect("tempdir"); + assert_eq!( + archive_service_log("managed service launched\n", results.path(), "s"), + "" + ); + + let dir = tempfile::tempdir().expect("tempdir"); + let missing = dir.path().join("missing.log"); + let reported = archive_service_log( + &format!(" log_path: {}\n", missing.display()), + results.path(), + "s", + ); + assert!( + reported.starts_with(" String { // ── Shared helpers ───────────────────────────────────────────────── +/// The suite's artifact directory. +/// +/// This is the ONLY path CI uploads (see the `upload-artifact` steps in +/// `.github/workflows/e2e-selfhosted.yml`), so anything a failure needs to +/// survive the run has to be written under here; a scenario's own isolated +/// `TempDir` is gone by the time the artifact is collected. +/// +/// Unlike [`results_dir`] this only computes the path and never creates it, so +/// it is safe to call from a failure path where a second panic would replace the +/// report being written. +pub fn results_path() -> PathBuf { + PathBuf::from(concat!(env!("CARGO_MANIFEST_DIR"), "/results")) +} + pub fn rocm_binary() -> String { std::env::var("ROCM_CLI_BINARY").unwrap_or_else(|_| "rocm".to_string()) } @@ -578,7 +592,7 @@ fn record_command(scenario: Option<&str>, args: &[&str], rc: i32, stdout: &str) "engine": engine, "engine_is_default": engine_is_default, }); - let dir = PathBuf::from(concat!(env!("CARGO_MANIFEST_DIR"), "/results")); + let dir = results_path(); if std::fs::create_dir_all(&dir).is_err() { return; } @@ -841,7 +855,7 @@ pub async fn send_chat(world: &mut E2eWorld) { // ── Runner ───────────────────────────────────────────────────────── fn results_dir() -> PathBuf { - let dir = PathBuf::from(concat!(env!("CARGO_MANIFEST_DIR"), "/results")); + let dir = results_path(); std::fs::create_dir_all(&dir).expect("failed to create results directory"); dir } diff --git a/tests/e2e-cucumber/tests/e2e/serving_steps.rs b/tests/e2e-cucumber/tests/e2e/serving_steps.rs index ca7b9da3..eacb11a2 100644 --- a/tests/e2e-cucumber/tests/e2e/serving_steps.rs +++ b/tests/e2e-cucumber/tests/e2e/serving_steps.rs @@ -10,7 +10,9 @@ use cucumber::{given, then, when}; use crate::E2eWorld; use e2e_cucumber::mock_server::MockServer; -use e2e_cucumber::serve_log::service_log_tail; +use e2e_cucumber::serve_log::{ + ServeAttempt, archive_service_log, serve_attempt_report, service_log_tail, +}; /// How long to wait for a freshly served model's endpoint to become ready. /// @@ -67,14 +69,94 @@ async fn model_is_ready(models_url: &str, expect_model: Option<&str>, timeout_se false } -async fn wait_for_model(models_url: &str, expect_model: Option<&str>, timeout_secs: u64) { - if model_is_ready(models_url, expect_model, timeout_secs).await { +/// The OpenAI-compatible base URL every GPU serve scenario serves on (see +/// [`SERVE_PORT`]), and the model listing readiness is judged by. +static SERVE_BASE_URL: LazyLock = + LazyLock::new(|| format!("http://127.0.0.1:{SERVE_PORT}/v1")); +static MODELS_URL: LazyLock = + LazyLock::new(|| format!("http://127.0.0.1:{SERVE_PORT}/v1/models")); + +/// The one-line verdict on a `--managed` serve that launched cleanly and then +/// never produced a usable endpoint. +/// +/// Says "exited 0" out loud because that is the whole difficulty of this failure: +/// nothing in the exit status, and nothing the CLI printed, distinguishes it from +/// a healthy serve — the evidence sections below it are the only account there is. +fn stall_headline(invocation: &str, ready_substr: &str, timeout_secs: u64) -> String { + let models_url = MODELS_URL.as_str(); + format!( + "{invocation} exited 0, but {models_url} never served `{ready_substr}` within \ + {timeout_secs}s — the launch reported success and the engine then failed on its own" + ) +} + +/// Everything a serve attempt left behind, gathered and rendered for a panic. +/// +/// The ORDER here is the load-bearing part, and it is why this is one function +/// rather than three calls at each site: the log must be read and copied out +/// while the service still owns it, because stopping the service both changes +/// what the log's last lines say and is the step most likely to fail outright. +/// +/// Mirrors what [`setup_gpu_model`] has always collected, so a stalled serve +/// reports the same evidence wherever it happens. +fn serve_failure_evidence( + world: &E2eWorld, + headline: &str, + device_state: &str, + stdout: &str, + stderr: &str, +) -> String { + let log_tail = service_log_tail(stdout); + // Copy the whole log into the results directory before the scenario's + // TempDir takes it: the tail below is enough to triage most stalls, but not + // one whose cause is in the engine's startup banner (see `archive_service_log`). + let archived_log = archive_service_log( + stdout, + &crate::results_path(), + world.current_scenario.as_deref().unwrap_or("scenario"), + ); + let stop_status = stop_scenario_services(world); + serve_attempt_report(&ServeAttempt { + headline, + device_state, + stdout, + stderr, + log_tail: &log_tail, + archived_log: &archived_log, + stop_status: &stop_status, + }) +} + +/// Launch a managed serve and wait until the endpoint really serves it, failing +/// with the full evidence bundle if it does not. +/// +/// Replaces the `run_rocm_ok` + readiness-poll pair the serve preconditions used +/// to open with. That pair cannot describe the failure this exists for: with +/// `--managed`, `rocm serve` returns once the supervisor is launched, so an +/// engine that dies afterwards exits **0** and the poll times out with nothing +/// attached — the CLI's output, the engine's log and the device state were all +/// dropped before the panic, which is why #260 could not be root-caused from a +/// CI artifact. A non-zero exit is reported the same way rather than through +/// `run_rocm_ok`, since the engine log explains those launches too. +async fn serve_and_wait(world: &mut E2eWorld, args: &[&str], model: &str, ready_substr: &str) { + let timeout_secs = serve_timeout_for(world); + let device_state = ensure_serve_port_free().await; + let (stdout, stderr, rc) = crate::run_rocm(world, args); + if rc == 0 && model_is_ready(&MODELS_URL, Some(ready_substr), timeout_secs).await { + world.endpoint = Some(SERVE_BASE_URL.to_string()); + world.model_name = Some(model.to_string()); return; } - match expect_model { - Some(m) => panic!("endpoint {models_url} did not serve model {m} within {timeout_secs}s"), - None => panic!("endpoint {models_url} not ready after {timeout_secs}s"), - } + let invocation = format!("`rocm {}`", args.join(" ")); + let headline = if rc == 0 { + stall_headline(&invocation, ready_substr, timeout_secs) + } else { + format!("{invocation} failed (rc={rc})") + }; + panic!( + "{}", + serve_failure_evidence(world, &headline, &device_state, &stdout, &stderr) + ); } /// The shared port every GPU serve scenario uses. Because scenarios run in @@ -419,7 +501,6 @@ async fn setup_gpu_model(world: &mut E2eWorld) { // linger on the GPU and oversubscribe it (which otherwise piles up serves // until the job times out). let (model, engine, ready_substr) = host_serve_target(); - let models_url = "http://127.0.0.1:11435/v1/models"; let timeout_secs = serve_timeout_for(world); let mut diagnostics = Vec::new(); // A managed vLLM launch can return `status: starting` without publishing the @@ -448,15 +529,15 @@ async fn setup_gpu_model(world: &mut E2eWorld) { let device_state = ensure_serve_port_free().await; let (stdout, stderr, rc) = crate::run_rocm(world, &["serve", model, "--engine", engine, "--managed"]); - if rc == 0 && model_is_ready(models_url, Some(ready_substr), timeout_secs).await { - world.endpoint = Some("http://127.0.0.1:11435/v1".to_string()); + if rc == 0 && model_is_ready(&MODELS_URL, Some(ready_substr), timeout_secs).await { + world.endpoint = Some(SERVE_BASE_URL.to_string()); world.model_name = Some(model.to_string()); return; } - // Read the log before stopping the service, so the tail reflects what the - // engine wrote on its own rather than anything the stop provokes. - let log_tail = service_log_tail(&stdout); - // Stop THIS attempt's stalled service before doing anything else. A vLLM + // `serve_failure_evidence` reads and copies out the log BEFORE it stops + // this attempt's stalled service, which matters twice over here. The tail + // then reflects what the engine wrote on its own rather than anything the + // stop provokes; and the stop itself is load-bearing for the RETRY. A vLLM // still in engine init has not bound the serve port yet, so the port kill // in `ensure_serve_port_free` cannot see it — it would survive into the // next attempt, hold its fraction-of-device memory reservation, and guarantee @@ -468,12 +549,12 @@ async fn setup_gpu_model(world: &mut E2eWorld) { // outcome is quoted: a stop that found no record (the launch had not yet // written one) or failed means the next attempt did NOT get a clean // device, and the failure says so instead of looking like a broken serve. - let stop_status = stop_scenario_services(world); - diagnostics.push(format!( - "attempt {attempt} (rc={rc}), {device_state}\ - \n--- STDOUT ---\n{stdout}\n--- STDERR ---\n{stderr}\ - \n--- SERVICE LOG (tail) ---\n{log_tail}\ - \n--- STOP ---\n{stop_status}" + diagnostics.push(serve_failure_evidence( + world, + &format!("attempt {attempt} of {attempts} (rc={rc})"), + &device_state, + &stdout, + &stderr, )); if attempt == attempts { break; @@ -488,6 +569,7 @@ async fn setup_gpu_model(world: &mut E2eWorld) { break; } } + let models_url = MODELS_URL.as_str(); panic!( "endpoint {models_url} did not serve model {ready_substr} after {made} attempt(s) of {timeout_secs}s each:\n{}", diagnostics.join("\n\n") @@ -501,20 +583,14 @@ async fn setup_lemonade_model(world: &mut E2eWorld) { // the parallel of setup_gpu_model's vLLM path, giving both engines their own // serve+inference coverage. Qwen3-0.6B-GGUF is the smallest lemonade recipe. let model = "Qwen3-0.6B-GGUF"; - ensure_serve_port_free().await; - crate::run_rocm_ok( - world, - &["serve", model, "--engine", "lemonade", "--managed"], - ); - world.endpoint = Some("http://127.0.0.1:11435/v1".to_string()); - world.model_name = Some(model.to_string()); // Wait for this lemonade model specifically (see setup_gpu_model): guards // against a leaked serve on the shared port. "Qwen3-0.6B" is the distinctive // substring (the endpoint reports it as e.g. Qwen3-0.6B-Q4_0.gguf). - wait_for_model( - "http://127.0.0.1:11435/v1/models", - Some("Qwen3-0.6B"), - serve_timeout_for(world), + serve_and_wait( + world, + &["serve", model, "--engine", "lemonade", "--managed"], + model, + "Qwen3-0.6B", ) .await; } @@ -525,18 +601,17 @@ async fn setup_lemonade_hf_checkpoint_model(world: &mut E2eWorld) { // EAI-8026) instead of the short-recipe-name router that `setup_lemonade_model` // exercises. Same underlying checkpoint (unsloth/Qwen3-0.6B-GGUF, Q4_0), so the // GGUF is already warm in the HF cache when both scenarios run in one job. + // + // This is the path #260 reports: on Strix Halo Windows the launch exits 0 and + // the endpoint never answers. `serve_and_wait` is what makes that outcome + // explain itself — the plain readiness poll this used to call reported the + // timeout and discarded everything that could say why. let model = "unsloth/Qwen3-0.6B-GGUF:Q4_0"; - ensure_serve_port_free().await; - crate::run_rocm_ok( + serve_and_wait( world, &["serve", model, "--engine", "lemonade", "--managed"], - ); - world.endpoint = Some("http://127.0.0.1:11435/v1".to_string()); - world.model_name = Some(model.to_string()); - wait_for_model( - "http://127.0.0.1:11435/v1/models", - Some("Qwen3-0.6B"), - serve_timeout_for(world), + model, + "Qwen3-0.6B", ) .await; } @@ -566,14 +641,11 @@ async fn setup_large_gpu_model(world: &mut E2eWorld) { } else { ("Qwen/Qwen3.6-27B", "vllm", "Qwen3.6-27B") }; - ensure_serve_port_free().await; - crate::run_rocm_ok(world, &["serve", model, "--engine", engine, "--managed"]); - world.endpoint = Some("http://127.0.0.1:11435/v1".to_string()); - world.model_name = Some(model.to_string()); - wait_for_model( - "http://127.0.0.1:11435/v1/models", - Some(ready_substr), - serve_timeout_for(world), + serve_and_wait( + world, + &["serve", model, "--engine", engine, "--managed"], + model, + ready_substr, ) .await; } @@ -655,30 +727,50 @@ async fn user_serves_default_engine(world: &mut E2eWorld) { // matrix requires this to resolve to lemonade on Instinct (EAI-7052). See that // fn's doc comment. let model = default_engine_serve_target(); - ensure_serve_port_free().await; + let device_state = ensure_serve_port_free().await; let (stdout, stderr, rc) = crate::run_rocm(world, &["serve", model, "--managed"]); // The model the CLI resolved (what actually gets served) can differ from the // requested id, so downstream reachability/readiness checks must look for the // resolved model on the shared port; fall back to the requested id. let served = resolved_model(&stdout).unwrap_or(model).to_string(); let ready_substr = ready_substr_for(&served).to_string(); + world.endpoint = Some(SERVE_BASE_URL.to_string()); + world.model_name = Some(served); + // Both streams and the rc are carried on the World so whichever Then step + // fires can explain itself: the scenarios behind this step assert on the + // engine the plan named and on reachability, and each of those reports the + // serve output when it fails. world.cli_output = Some(stdout); - // rc is asserted by a later Then step, so stderr has to survive with it — - // otherwise that deferred assertion reports a failure it cannot explain. world.cli_stderr = Some(stderr); world.cli_rc = Some(rc); - world.endpoint = Some("http://127.0.0.1:11435/v1".to_string()); - world.model_name = Some(served); - if rc == 0 { - // Wait for THE RESOLVED model specifically (not just any 200) — the shared - // port 11435 may still answer from a prior scenario's leaked serve, and a - // model-agnostic wait would then proceed against the wrong server. - wait_for_model( - "http://127.0.0.1:11435/v1/models", - Some(&ready_substr), - serve_timeout_for(world), - ) - .await; + // A non-zero rc is deliberately NOT failed here. This is a `When`: the CLI + // still printed the plan line the scenario is about, so failing on the exit + // code would pre-empt the Then step that names the actual disagreement with a + // blunter message. The other outcome — an exit-0 serve whose endpoint never + // answers — has no Then step to catch it, so this step reports it, with the + // same evidence a GPU serve collects rather than the bare timeout line that + // left #260 undiagnosable. + // + // Wait for THE RESOLVED model specifically (not just any 200) — the shared port + // 11435 may still answer from a prior scenario's leaked serve, and a + // model-agnostic wait would then proceed against the wrong server. + let timeout_secs = serve_timeout_for(world); + if rc == 0 && !model_is_ready(&MODELS_URL, Some(&ready_substr), timeout_secs).await { + let headline = stall_headline( + &format!("`rocm serve {model} --managed`"), + &ready_substr, + timeout_secs, + ); + panic!( + "{}", + serve_failure_evidence( + world, + &headline, + &device_state, + world.cli_output.as_deref().unwrap_or_default(), + world.cli_stderr.as_deref().unwrap_or_default(), + ) + ); } } @@ -904,7 +996,7 @@ fn resolved_model(output: &str) -> Option<&str> { } /// A distinctive substring of a model id that appears in the served endpoint's -/// `/v1/models` response, for `wait_for_model`'s containment check. Strips the +/// `/v1/models` response, for [`model_is_ready`]'s containment check. Strips the /// `org/` prefix and the `-GGUF` catalog marker so a resolved catalog id /// (`Qwen3-4B-Instruct-2507-GGUF`) matches the concrete artifact the endpoint /// reports (`Qwen3-4B-Instruct-2507-Q4_K_M.gguf`) — both share the base