From e23202264712d3f70c8e22086eb5000e06a022d6 Mon Sep 17 00:00:00 2001 From: Roman Inflianskas Date: Mon, 17 Aug 2026 11:53:28 +0000 Subject: [PATCH 1/2] test(e2e): explain a managed serve that exits 0 and never serves MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A `rocm serve --managed` returns as soon as the supervisor is launched, so an engine that dies afterwards leaves a zero exit code. The serve preconditions paired `run_rocm_ok` with a bare readiness poll, and that pair has nothing to say about this case: the poll panicked with only its timeout line while the CLI's output, the engine's log and the device state were all discarded. #260 is stuck there — the failing endpoint is reproducible only on a self-hosted Windows runner, and every run destroys its own evidence. Give that path the diagnostics the GPU serve step already collected, and share one collector between them so they cannot drift apart. A stalled serve now reports the invocation and exit code, the device state it started on, both CLI streams, the tail of the engine's own log, and how stopping the service went. The log itself lives in the scenario's isolated temp dir and dies with it, while CI uploads only the results directory, so the full file is now copied there too. The tail alone cannot show the startup banner naming the backend and device that were selected, which is exactly what an engine that never answers needs to be read against. Oversized logs keep both ends with the elision marked, so a runaway log cannot inflate the artifact. This is observability only. It does not fix #260, which stays open. Signed-off-by: Roman Inflianskas --- tests/e2e-cucumber/src/lib.rs | 27 +- tests/e2e-cucumber/src/serve_log.rs | 380 +++++++++++++++++- tests/e2e-cucumber/tests/e2e.rs | 20 +- tests/e2e-cucumber/tests/e2e/serving_steps.rs | 218 +++++++--- 4 files changed, 568 insertions(+), 77 deletions(-) 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..0d30f9f6 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,91 @@ 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. +const SERVE_BASE_URL: &str = "http://127.0.0.1:11435/v1"; +const MODELS_URL: &str = "http://127.0.0.1:11435/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 { + 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 +498,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 +526,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 +546,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; @@ -489,7 +567,7 @@ async fn setup_gpu_model(world: &mut E2eWorld) { } } panic!( - "endpoint {models_url} did not serve model {ready_substr} after {made} attempt(s) of {timeout_secs}s each:\n{}", + "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 +579,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 +597,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 +637,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 +723,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 +992,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 From 2d7cfd4bae0780f7091bed2884c8e2b291d183a3 Mon Sep 17 00:00:00 2001 From: Roman Inflianskas Date: Thu, 20 Aug 2026 10:10:31 +0000 Subject: [PATCH 2/2] test(e2e): derive serve URLs from SERVE_PORT SERVE_BASE_URL and MODELS_URL hardcoded the port literal separately from SERVE_PORT, so the three could drift out of sync. Signed-off-by: Roman Inflianskas --- tests/e2e-cucumber/tests/e2e/serving_steps.rs | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/tests/e2e-cucumber/tests/e2e/serving_steps.rs b/tests/e2e-cucumber/tests/e2e/serving_steps.rs index 0d30f9f6..eacb11a2 100644 --- a/tests/e2e-cucumber/tests/e2e/serving_steps.rs +++ b/tests/e2e-cucumber/tests/e2e/serving_steps.rs @@ -71,8 +71,10 @@ async fn model_is_ready(models_url: &str, expect_model: Option<&str>, timeout_se /// The OpenAI-compatible base URL every GPU serve scenario serves on (see /// [`SERVE_PORT`]), and the model listing readiness is judged by. -const SERVE_BASE_URL: &str = "http://127.0.0.1:11435/v1"; -const MODELS_URL: &str = "http://127.0.0.1:11435/v1/models"; +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. @@ -81,8 +83,9 @@ const MODELS_URL: &str = "http://127.0.0.1:11435/v1/models"; /// 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 \ + "{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" ) } @@ -139,7 +142,7 @@ async fn serve_and_wait(world: &mut E2eWorld, args: &[&str], model: &str, ready_ 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 { + 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; @@ -526,7 +529,7 @@ 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 { + 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; @@ -566,8 +569,9 @@ 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{}", + "endpoint {models_url} did not serve model {ready_substr} after {made} attempt(s) of {timeout_secs}s each:\n{}", diagnostics.join("\n\n") ); } @@ -751,7 +755,7 @@ async fn user_serves_default_engine(world: &mut E2eWorld) { // 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 { + 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,