From 9a8fc69d823976c8846a95602b4710fa3333b928 Mon Sep 17 00:00:00 2001 From: Jean Mertz Date: Thu, 9 Jul 2026 23:52:32 +0200 Subject: [PATCH 1/3] chore(tools): Parse JSON trace-log marker in debug_jp `debug_jp` locates jp's trace log by scanning stderr for the text marker `Full trace log written to: `. When jp runs with `--format json` or `json-pretty`, it emits a `{"trace_log": ""}` object instead, so the tool failed to find the trace file and reported a spurious "trace log not found" error for any JSON-format run. `trace_parse` gains `extract_trace_path`, which recognizes either shape, and `is_trace_path_marker_line`, used to strip the marker line from the stderr shown in rendered reports so it doesn't show up twice (once in the footer, once in the raw stderr dump). Signed-off-by: Jean Mertz --- .config/jp/tools/src/debug_jp/trace.rs | 34 ++++++++----------- .config/jp/tools/src/debug_jp/trace_tests.rs | 32 +++++++++++++++++ .../jp/tools/src/debug_jp/util/trace_parse.rs | 33 ++++++++++++++++++ .../src/debug_jp/util/trace_parse_tests.rs | 28 +++++++++++++++ .../tools/src/debug_jp/util/trace_render.rs | 11 +++--- .../src/debug_jp/util/trace_render_tests.rs | 15 ++++++++ 6 files changed, 130 insertions(+), 23 deletions(-) diff --git a/.config/jp/tools/src/debug_jp/trace.rs b/.config/jp/tools/src/debug_jp/trace.rs index 990766544..bda8ef108 100644 --- a/.config/jp/tools/src/debug_jp/trace.rs +++ b/.config/jp/tools/src/debug_jp/trace.rs @@ -2,7 +2,9 @@ //! //! Launches `jp` inside the sandbox with `JP_DEBUG=1` set. //! `jp_cli` persists its tracing-subscriber output to a system temp file and -//! prints `Full trace log written to: ` on stderr at exit. +//! announces the path on stderr at exit, either as a `Full trace log written +//! to: ` line (text output) or a `{"trace_log": ""}` object (JSON +//! output). //! We parse that line, copy the file out to the real workspace so it survives //! sandbox cleanup, filter the events by level/target/grep, and render the //! result in a compact logfmt-like format. @@ -22,17 +24,13 @@ use crate::{ build::{self, BuildSpec}, launch::{LaunchResult, LaunchSpec, Launcher, RealLauncher, Timeouts}, sandbox::{Sandbox, SandboxOpts}, - trace_parse::{self, Level, TraceEvent}, + trace_parse::{self, Level, TRACE_PATH_PREFIX, TraceEvent}, trace_render::{self, CommandRun, OutputPaths}, with_termination_note, }, util::{ToolResult, error, runner::DuctProcessRunner}, }; -/// Marker line `jp_cli::run` writes to stderr when `JP_DEBUG=1` and the output -/// format is text (we never pass `--format=json`, so this is what we get). -const TRACE_PATH_PREFIX: &str = "Full trace log written to: "; - /// Tool entrypoint. /// Dispatches between the format-args preview and the live execution. #[allow(clippy::unused_async, reason = "awaited by the debug_jp dispatcher")] @@ -386,28 +384,26 @@ fn run_one( ) -> Result { let launch_result = launcher.run(spec, timeouts, &mut |_| {})?; - // jp prints `Full trace log written to: ` on stderr right before - // exit. The path is in the system temp dir (e.g. `/var/folders/...`), - // outside the sandbox. A force-killed jp never flushes, so fold the - // termination note into the error when the marker is absent. - let Some(trace_line) = launch_result - .stderr - .lines() - .find_map(|line| line.strip_prefix(TRACE_PATH_PREFIX)) - else { + // jp announces the trace path on stderr right before exit, either as a + // text marker line or a `trace_log` JSON field (depending on + // `--format`). The path is in the system temp dir (e.g. + // `/var/folders/...`), outside the sandbox. A force-killed jp never + // flushes, so fold the termination note into the error when the marker + // is absent. + let Some(trace_path) = trace_parse::extract_trace_path(&launch_result.stderr) else { let note = launch_result .note() .map(|n| format!("{n}\n\n")) .unwrap_or_default(); return Err(format!( - "{note}Did not find `{TRACE_PATH_PREFIX}` in jp's stderr. jp may have exited \ - before the tracing layer flushed, or stderr was redirected. Last 20 lines of \ - stderr:\n{}", + "{note}Did not find a `{TRACE_PATH_PREFIX}` line or a `trace_log` JSON field in \ + jp's stderr. jp may have exited before the tracing layer flushed, or stderr was \ + redirected. Last 20 lines of stderr:\n{}", tail_lines(&launch_result.stderr, 20) ) .into()); }; - let trace_src = Utf8PathBuf::from(trace_line.trim()); + let trace_src = Utf8PathBuf::from(trace_path); // Copy the trace log into the real workspace so it survives the system // temp dir's eventual cleanup and stays alongside other profile output. diff --git a/.config/jp/tools/src/debug_jp/trace_tests.rs b/.config/jp/tools/src/debug_jp/trace_tests.rs index eef8909e7..af91ed8cb 100644 --- a/.config/jp/tools/src/debug_jp/trace_tests.rs +++ b/.config/jp/tools/src/debug_jp/trace_tests.rs @@ -56,6 +56,38 @@ fn renders_report_from_launched_trace_log() { assert!(root.join("tmp/profiling").exists()); } +#[test] +fn renders_report_from_json_format_marker_line() { + // `--format json` / `json-pretty` makes jp emit a `{"trace_log": ...}` + // object on stderr instead of the text marker line. + let workspace = camino_tempfile::tempdir().unwrap(); + let root = workspace.path(); + + let trace_log = root.join("trace-src.jsonl"); + std::fs::write(&trace_log, "").unwrap(); + let launcher = MockLauncher::returning(launched( + format!("{{\"trace_log\":\"{trace_log}\"}}\n"), + Termination::Exited, + )); + + let outcome = execute( + root, + &spec(root), + Level::Info, + None, + None, + &launcher, + Timeouts::DEFAULT, + ) + .unwrap(); + + let Outcome::Success { content } = outcome else { + panic!("expected a success outcome"); + }; + assert!(!content.is_empty()); + assert!(root.join("tmp/profiling").exists()); +} + #[test] fn renders_combined_report_for_command_sequence() { let workspace = camino_tempfile::tempdir().unwrap(); diff --git a/.config/jp/tools/src/debug_jp/util/trace_parse.rs b/.config/jp/tools/src/debug_jp/util/trace_parse.rs index 65bbf0544..5777177f8 100644 --- a/.config/jp/tools/src/debug_jp/util/trace_parse.rs +++ b/.config/jp/tools/src/debug_jp/util/trace_parse.rs @@ -7,6 +7,10 @@ use serde::Deserialize; use serde_json::{Map, Value}; +/// Text-format marker jp writes to stderr, right before exit, when `JP_DEBUG=1` +/// and the output format is human-readable text. +pub(crate) const TRACE_PATH_PREFIX: &str = "Full trace log written to: "; + /// Severity, ordered so `level >= Level::Info` is meaningful. #[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] pub(crate) enum Level { @@ -67,6 +71,35 @@ pub(crate) fn parse_lines(text: &str) -> Vec { text.lines().filter_map(parse_line).collect() } +/// Extract the trace log path jp writes to stderr right before exit. +/// +/// jp emits `Full trace log written to: ` when the output format is text, +/// or a `{"trace_log": ""}` JSON object when the format is JSON or +/// JSON-pretty. +/// This checks each stderr line for either shape. +pub(crate) fn extract_trace_path(stderr: &str) -> Option { + stderr.lines().find_map(parse_trace_path_line) +} + +/// True for the stderr line jp emits to announce the trace log path, in either +/// the text or JSON marker format. +pub(crate) fn is_trace_path_marker_line(line: &str) -> bool { + parse_trace_path_line(line).is_some() +} + +fn parse_trace_path_line(line: &str) -> Option { + if let Some(path) = line.strip_prefix(TRACE_PATH_PREFIX) { + return Some(path.trim().to_owned()); + } + match serde_json::from_str::(line).ok()? { + Value::Object(obj) => match obj.get("trace_log")? { + Value::String(path) => Some(path.clone()), + _ => None, + }, + _ => None, + } +} + fn parse_line(line: &str) -> Option { if line.trim().is_empty() { return None; diff --git a/.config/jp/tools/src/debug_jp/util/trace_parse_tests.rs b/.config/jp/tools/src/debug_jp/util/trace_parse_tests.rs index a59609e17..0131db10d 100644 --- a/.config/jp/tools/src/debug_jp/util/trace_parse_tests.rs +++ b/.config/jp/tools/src/debug_jp/util/trace_parse_tests.rs @@ -81,6 +81,34 @@ fn parse_drops_lines_with_unknown_level() { assert!(events.is_empty()); } +#[test] +fn extract_trace_path_reads_text_marker_line() { + let stderr = "some noise\nFull trace log written to: /tmp/x.jsonl\n"; + assert_eq!(extract_trace_path(stderr), Some("/tmp/x.jsonl".to_owned())); +} + +#[test] +fn extract_trace_path_reads_json_marker_line() { + // jp emits this shape instead of the text marker when `--format` is + // json or json-pretty. + let stderr = "some noise\n{\"trace_log\":\"/tmp/x.jsonl\"}\n"; + assert_eq!(extract_trace_path(stderr), Some("/tmp/x.jsonl".to_owned())); +} + +#[test] +fn extract_trace_path_returns_none_without_a_marker() { + assert_eq!(extract_trace_path("nothing relevant here\n"), None); +} + +#[test] +fn is_trace_path_marker_line_matches_both_formats() { + assert!(is_trace_path_marker_line( + "Full trace log written to: /tmp/x.jsonl" + )); + assert!(is_trace_path_marker_line(r#"{"trace_log":"/tmp/x.jsonl"}"#)); + assert!(!is_trace_path_marker_line("some real error")); +} + #[test] fn parse_preserves_field_insertion_order() { // serde_json's `preserve_order` feature is enabled at the workspace level. diff --git a/.config/jp/tools/src/debug_jp/util/trace_render.rs b/.config/jp/tools/src/debug_jp/util/trace_render.rs index 5af89265f..59c66a623 100644 --- a/.config/jp/tools/src/debug_jp/util/trace_render.rs +++ b/.config/jp/tools/src/debug_jp/util/trace_render.rs @@ -30,7 +30,10 @@ use std::{fmt::Write as _, time::Duration}; use serde_json::Value; -use crate::debug_jp::util::{launch::LaunchResult, trace_parse::TraceEvent}; +use crate::debug_jp::util::{ + launch::LaunchResult, + trace_parse::{self, TraceEvent}, +}; /// Hard ceiling on target column padding. /// Targets longer than this are printed at full width, breaking alignment for @@ -257,13 +260,13 @@ fn write_multi_footer(out: &mut String, runs: &[CommandRun<'_>]) { } } -/// Drop the `Full trace log written to: ` line jp emits when `JP_DEBUG=1` -/// is set. +/// Drop the stderr line jp emits to announce the trace log path (text marker or +/// `trace_log` JSON field, depending on `--format`). /// The path is already in the footer. fn strip_trace_path_marker(stderr: &str) -> String { stderr .lines() - .filter(|line| !line.starts_with("Full trace log written to: ")) + .filter(|line| !trace_parse::is_trace_path_marker_line(line)) .collect::>() .join("\n") } diff --git a/.config/jp/tools/src/debug_jp/util/trace_render_tests.rs b/.config/jp/tools/src/debug_jp/util/trace_render_tests.rs index 165e5737d..4288e347e 100644 --- a/.config/jp/tools/src/debug_jp/util/trace_render_tests.rs +++ b/.config/jp/tools/src/debug_jp/util/trace_render_tests.rs @@ -306,6 +306,21 @@ fn render_strips_trace_path_marker_from_stderr() { assert!(!stderr_section.contains("Full trace log written to")); } +#[test] +fn render_strips_json_trace_path_marker_from_stderr() { + // jp emits this shape instead of the text marker when `--format` is + // json or json-pretty; it must be stripped the same way. + let mut launch = fixture_launch(); + launch.stderr = "some real error\n{\"trace_log\":\"/tmp/x\"}\n".into(); + + let report = render(&[], 0, &launch, &["c".into()], fixture_paths()); + let stderr_start = report.find("## stderr").unwrap(); + let footer_start = report.find("**Files:**").unwrap(); + let stderr_section = &report[stderr_start..footer_start]; + assert!(stderr_section.contains("some real error")); + assert!(!stderr_section.contains("trace_log")); +} + #[test] fn render_footer_lists_all_three_sidecar_files() { let report = render(&[], 0, &fixture_launch(), &["c".into()], fixture_paths()); From a5ac1d3c9a41aead1b14a978388f0aaedadcc73a Mon Sep 17 00:00:00 2001 From: Jean Mertz Date: Fri, 10 Jul 2026 00:16:17 +0200 Subject: [PATCH 2/3] fixup! chore(tools): Parse JSON trace-log marker in debug_jp Signed-off-by: Jean Mertz --- .config/jp/tools/src/debug_jp/trace_tests.rs | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/.config/jp/tools/src/debug_jp/trace_tests.rs b/.config/jp/tools/src/debug_jp/trace_tests.rs index af91ed8cb..01ed3e0f6 100644 --- a/.config/jp/tools/src/debug_jp/trace_tests.rs +++ b/.config/jp/tools/src/debug_jp/trace_tests.rs @@ -65,10 +65,11 @@ fn renders_report_from_json_format_marker_line() { let trace_log = root.join("trace-src.jsonl"); std::fs::write(&trace_log, "").unwrap(); - let launcher = MockLauncher::returning(launched( - format!("{{\"trace_log\":\"{trace_log}\"}}\n"), - Termination::Exited, - )); + // Built via `serde_json::json!` (like the real jp code) rather than + // string interpolation, so the path's backslashes on Windows get + // properly JSON-escaped. + let marker = serde_json::json!({ "trace_log": trace_log.as_str() }); + let launcher = MockLauncher::returning(launched(format!("{marker}\n"), Termination::Exited)); let outcome = execute( root, From b1750024b9d761ce8c1173b4e4d478c59fe9d471 Mon Sep 17 00:00:00 2001 From: Jean Mertz Date: Fri, 10 Jul 2026 06:45:49 +0200 Subject: [PATCH 3/3] fixup! chore(tools): Parse JSON trace-log marker in debug_jp Signed-off-by: Jean Mertz --- .config/jp/tools/src/debug_jp/trace.rs | 95 ++++++++++++-------- .config/jp/tools/src/debug_jp/trace_tests.rs | 59 ++++++++++++ .config/jp/tools/src/debug_jp/util/launch.rs | 7 +- crates/jp_cli/src/lib.rs | 47 +++++++--- crates/jp_cli/src/lib_tests.rs | 24 +++++ 5 files changed, 179 insertions(+), 53 deletions(-) diff --git a/.config/jp/tools/src/debug_jp/trace.rs b/.config/jp/tools/src/debug_jp/trace.rs index bda8ef108..1ec203139 100644 --- a/.config/jp/tools/src/debug_jp/trace.rs +++ b/.config/jp/tools/src/debug_jp/trace.rs @@ -1,13 +1,15 @@ //! `debug_jp_trace` — capture and render `JP_DEBUG=1` trace logs. //! -//! Launches `jp` inside the sandbox with `JP_DEBUG=1` set. -//! `jp_cli` persists its tracing-subscriber output to a system temp file and -//! announces the path on stderr at exit, either as a `Full trace log written +//! Launches `jp` inside the sandbox with `JP_DEBUG=1` set and `--log-file` +//! pointing at a path in the real workspace, so the trace log lands at a known +//! location that survives sandbox cleanup — even when jp is force-killed, +//! since the file layer writes events as they happen. +//! When the file is missing (jp exited before logging was configured), we fall +//! back to the path jp announces on stderr at exit: a `Full trace log written //! to: ` line (text output) or a `{"trace_log": ""}` object (JSON //! output). -//! We parse that line, copy the file out to the real workspace so it survives -//! sandbox cleanup, filter the events by level/target/grep, and render the -//! result in a compact logfmt-like format. +//! The events are then filtered by level/target/grep and rendered in a compact +//! logfmt-like format. use std::{ fs, @@ -107,14 +109,17 @@ fn format_preview( out.push_str("cargo build --profile profiling -p jp_cli --bin jp\n"); if let [command] = commands { out.push_str(&format!( - "JP_DEBUG=1 target/profiling/jp {} # invoked by absolute path\n", + "JP_DEBUG=1 target/profiling/jp --log-file tmp/profiling/trace-.jsonl {} # \ + invoked by absolute path\n", command.join(" ") )); } else { out.push_str("# commands run in sequence in one sandbox (state persists between them):\n"); for (i, command) in commands.iter().enumerate() { out.push_str(&format!( - "JP_DEBUG=1 target/profiling/jp {} # command {}\n", + "JP_DEBUG=1 target/profiling/jp --log-file tmp/profiling/trace--cmd{}.jsonl \ + {} # command {}\n", + i + 1, command.join(" "), i + 1 )); @@ -361,12 +366,13 @@ struct CommandArtifacts { stderr_dst: Utf8PathBuf, } -/// Launch jp via `launcher`, copy its trace log and streams into `out_dir` +/// Launch jp via `launcher`, collect its trace log and streams into `out_dir` /// (keyed by `