Skip to content

Commit 8763696

Browse files
committed
test(snapshots): add PTY step trace to reproduce the Linux hang
Temporary diagnostic (mirrors feat/cwd-flag #2031): bound the PTY step at 10 min, write START/phase/END step traces to VP_SNAP_TRACE_FILE, and print them from an if: always() step so a wedged case survives the killed step. Lets us reproduce and diagnose the recurring Namespace-Linux PTY hang from this PR too. Revert once the root cause is found.
1 parent de07915 commit 8763696

2 files changed

Lines changed: 73 additions & 0 deletions

File tree

  • .github/workflows
  • crates/vite_cli_snapshots/tests/cli_snapshots

.github/workflows/ci.yml

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1086,12 +1086,36 @@ jobs:
10861086
|| echo "prewarm failed; cases will download the runtime on demand"
10871087
10881088
- name: Run PTY snapshot tests
1089+
# Bound the step: the suite runs in well under 2 min, but an
1090+
# interactive PTY case can wedge unbounded on the Namespace runner
1091+
# (PTY spawn/teardown flakiness, the Linux analog of the ConPTY
1092+
# blocking that keeps cli-snapshot-test-windows on GitHub-hosted
1093+
# runners). Without this, a wedged case burns the 6h job default and
1094+
# never flushes the step log; the timeout fails fast and preserves it.
1095+
timeout-minutes: 10
10891096
run: |
10901097
VP_SNAP_GLOBAL_VP="$HOME/.vite-plus/bin/vp" \
10911098
VP_SNAP_JS_RUNTIME_DIR="$HOME/.vite-plus/js_runtime" \
10921099
cargo test -p vite_cli_snapshots
10931100
env:
10941101
RUST_BACKTRACE: '1'
1102+
# Diagnostic step tracing to a file (see snap_trace): a step that
1103+
# logs START without END is the one that wedged. Written to a file
1104+
# (not the step log) because GitHub discards a timed-out step's log;
1105+
# the next step prints it. Investigating the recurring Namespace-
1106+
# Linux PTY wedge that survives the spawn bound.
1107+
VP_SNAP_TRACE_FILE: ${{ runner.temp }}/pty-trace.log
1108+
1109+
- name: Print PTY trace
1110+
# Runs even when the step above is killed by its timeout, so the trace
1111+
# survives the wedge (that step's own log does not).
1112+
if: always()
1113+
run: |
1114+
if [ -f "${{ runner.temp }}/pty-trace.log" ]; then
1115+
cat "${{ runner.temp }}/pty-trace.log"
1116+
else
1117+
echo "no pty-trace file (VP_SNAP_TRACE_FILE unwritten)"
1118+
fi
10951119
10961120
# Runs the PTY snapshot suite (crates/vite_cli_snapshots) on Windows with
10971121
# BOTH vp flavors, without a Rust toolchain on the runner: the test binary

crates/vite_cli_snapshots/tests/cli_snapshots/main.rs

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,37 @@ const STEP_TIMEOUT: Duration =
3939
/// Screen size for the PTY terminal. Large enough to avoid line wrapping.
4040
const SCREEN_SIZE: ScreenSize = ScreenSize { rows: 500, cols: 500 };
4141

42+
/// Diagnostic step tracing. A step that logs `START` without a matching
43+
/// `END` is the one that wedged; the phase markers localize within it.
44+
///
45+
/// `VP_SNAP_TRACE_FILE` appends to that file (each line flushed) — use this in
46+
/// CI: a step killed by its timeout has its own log discarded by GitHub, but a
47+
/// file on disk survives and a later `if: always()` step can print it.
48+
/// `VP_SNAP_TRACE=1` writes to stderr instead, for local runs.
49+
fn snap_trace(args: std::fmt::Arguments<'_>) {
50+
use std::io::Write as _;
51+
static SINK: std::sync::LazyLock<Option<std::sync::Mutex<std::fs::File>>> =
52+
std::sync::LazyLock::new(|| {
53+
let path = std::env::var_os("VP_SNAP_TRACE_FILE")?;
54+
std::fs::OpenOptions::new()
55+
.create(true)
56+
.append(true)
57+
.open(path)
58+
.ok()
59+
.map(std::sync::Mutex::new)
60+
});
61+
if let Some(file) = SINK.as_ref() {
62+
if let Ok(mut file) = file.lock() {
63+
let _ = writeln!(file, "[pty-trace] {args}");
64+
let _ = file.flush();
65+
}
66+
} else if std::env::var_os("VP_SNAP_TRACE").is_some_and(|v| v == "1") {
67+
let mut err = std::io::stderr().lock();
68+
let _ = writeln!(err, "[pty-trace] {args}");
69+
let _ = err.flush();
70+
}
71+
}
72+
4273
/// Raw serde shape for a step: bare argv array or full table.
4374
#[derive(serde::Deserialize, Debug)]
4475
#[serde(untagged)]
@@ -386,6 +417,7 @@ fn load_snapshots_file(fixture_path: &Path) -> SnapshotsFile {
386417
}
387418
}
388419

420+
#[derive(Debug)]
389421
enum TerminationState {
390422
Exited(i64),
391423
TimedOut,
@@ -896,6 +928,8 @@ fn run_case(
896928
}
897929
}
898930

931+
let trace_tag = format!("{fixture_name}::{}::{}", case.name, flavor.as_str());
932+
899933
let mut timeout_error: Option<String> = None;
900934
let mut step_index = 0;
901935
while step_index < case.steps.len() {
@@ -906,6 +940,11 @@ fn run_case(
906940
let step_env: &BTreeMap<String, OsString> = &step_env;
907941
let timeout = step.timeout(step_default_timeout);
908942

943+
snap_trace(format_args!(
944+
"{trace_tag} step {step_index} START tty={} timeout={timeout:?} {:?}",
945+
step.tty, argv
946+
));
947+
909948
let (termination_state, raw_output) = if step.tty {
910949
'tty: {
911950
let mut cmd = CommandBuilder::new(&program);
@@ -938,10 +977,14 @@ fn run_case(
938977
let _ = terminal.child_handle.clone().kill();
939978
}
940979
});
980+
snap_trace(format_args!("{trace_tag} step {step_index} PTY spawn dispatched"));
941981
let terminal = match spawn_rx.recv_timeout(timeout) {
942982
Ok(Ok(terminal)) => terminal,
943983
Ok(Err(err)) => panic!("failed to spawn PTY terminal: {err}"),
944984
Err(mpsc::RecvTimeoutError::Timeout) => {
985+
snap_trace(format_args!(
986+
"{trace_tag} step {step_index} PTY spawn TIMED OUT"
987+
));
945988
break 'tty (
946989
TerminationState::TimedOut,
947990
"(PTY spawn did not complete)".to_string(),
@@ -951,6 +994,7 @@ fn run_case(
951994
panic!("PTY spawn thread panicked");
952995
}
953996
};
997+
snap_trace(format_args!("{trace_tag} step {step_index} PTY spawned, driving"));
954998
let mut killer = terminal.child_handle.clone();
955999
let interactions = step.interactions.clone();
9561000
let formatted_snapshot = step.formatted_snapshot;
@@ -1018,6 +1062,9 @@ fn run_case(
10181062
let _ = tx.send(i64::from(status.exit_code()));
10191063
});
10201064

1065+
snap_trace(format_args!(
1066+
"{trace_tag} step {step_index} interactions dispatched, waiting for exit"
1067+
));
10211068
match rx.recv_timeout(timeout) {
10221069
Ok(exit_code) => {
10231070
let output = output.lock().unwrap().clone();
@@ -1044,6 +1091,8 @@ fn run_case(
10441091
(state, block)
10451092
};
10461093

1094+
snap_trace(format_args!("{trace_tag} step {step_index} END {termination_state:?}"));
1095+
10471096
// Blank line separator before every `##`.
10481097
doc.push('\n');
10491098
doc.push_str("## `");

0 commit comments

Comments
 (0)