chore(tools): Parse JSON trace-log marker in debug_jp

.config/jp/tools/src/debug_jp/trace.rs

@@ -1,11 +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
-//! prints `Full trace log written to: <path>` on stderr at exit.
-//! 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.
+//! 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: <path>` line (text output) or a `{"trace_log": "<path>"}` object (JSON
+//! output).
+//! The events are then filtered by level/target/grep and rendered in a compact
+//! logfmt-like format.
 
 use std::{
     fs,
@@ -22,17 +26,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")]
@@ -109,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-<ts>.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-<ts>-cmd{}.jsonl \
+                 {}    # command {}\n",
+                i + 1,
                 command.join(" "),
                 i + 1
             ));
@@ -363,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 `<ts><label>`), and return the filtered events.
 ///
 /// `label` distinguishes a command's files within a sequence (e.g. `-cmd1`); it
 /// is empty for a single-command run, preserving the standalone file names.
-/// Returns an error when jp exits without flushing its trace log.
+/// Returns an error when no trace log was produced (jp exited before its
+/// logging was configured, and announced no path on stderr).
 #[allow(
     clippy::too_many_arguments,
     reason = "thin internal seam over the launch+copy step"
@@ -384,40 +388,49 @@ fn run_one(
     ts: u64,
     label: &str,
 ) -> Result<CommandArtifacts, Error> {
-    let launch_result = launcher.run(spec, timeouts, &mut |_| {})?;
-
-    // jp prints `Full trace log written to: <path>` 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 {
-        let note = launch_result
-            .note()
-            .map(|n| format!("{n}\n\n"))
-            .unwrap_or_default();
-        return Err(format!(
-            "{note}Did not find `{TRACE_PATH_PREFIX}<path>` 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());
-
-    // Copy the trace log into the real workspace so it survives the system
-    // temp dir's eventual cleanup and stays alongside other profile output.
-    // Stdout/stderr are dumped alongside so each command's trace + streams are
-    // one cohesive set of files keyed by `<ts><label>`.
+    // Each command's trace + streams are one cohesive set of files keyed by
+    // `<ts><label>`.
     let trace_dst = out_dir.join(format!("trace-{ts}{label}.jsonl"));
     let stdout_dst = out_dir.join(format!("trace-{ts}{label}-stdout.txt"));
     let stderr_dst = out_dir.join(format!("trace-{ts}{label}-stderr.txt"));
-    fs::copy(&trace_src, &trace_dst)
-        .map_err(|e| format!("Failed to copy trace log from {trace_src} to {trace_dst}: {e}"))?;
+
+    // Pin the trace log to `trace_dst` via `--log-file`, so its location is
+    // known without a clean exit. jp's file layer writes events as they
+    // happen, so even a force-killed run leaves a partial-but-parseable log
+    // there. The flag goes on a copy: `spec.args` is also the user-visible
+    // command line in reports and error messages.
+    let mut launch_spec = spec.clone();
+    launch_spec.args = ["--log-file".to_owned(), trace_dst.to_string()]
+        .into_iter()
+        .chain(spec.args.iter().cloned())
+        .collect();
+
+    let launch_result = launcher.run(&launch_spec, timeouts, &mut |_| {})?;
+
+    // Fallback: jp exited before creating `trace_dst` (or ignored the flag).
+    // Locate the trace via the path jp announces on stderr at exit — a text
+    // marker line or a `trace_log` JSON field, depending on `--format` — and
+    // copy it out of the system temp dir into the real workspace.
+    if !trace_dst.exists() {
+        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}No trace log was written to {trace_dst}, and jp's stderr contains neither \
+                 a `{TRACE_PATH_PREFIX}<path>` line nor a `trace_log` JSON field. jp may have \
+                 exited before its logging was configured. Last 20 lines of stderr:\n{}",
+                tail_lines(&launch_result.stderr, 20)
+            )
+            .into());
+        };
+        let trace_src = Utf8PathBuf::from(trace_path);
+        fs::copy(&trace_src, &trace_dst).map_err(|e| {
+            format!("Failed to copy trace log from {trace_src} to {trace_dst}: {e}")
+        })?;
+    }
+
     fs::write(&stdout_dst, &launch_result.stdout)
         .map_err(|e| format!("Failed to write stdout capture to {stdout_dst}: {e}"))?;
     fs::write(&stderr_dst, &launch_result.stderr)

.config/jp/tools/src/debug_jp/trace_tests.rs

@@ -56,6 +56,39 @@ 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();
+    // 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,
+        &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();
@@ -115,6 +148,65 @@ fn renders_combined_report_for_command_sequence() {
     assert!(profiling.exists());
 }
 
+/// A launcher that emulates jp's `--log-file` handling: it writes `content` to
+/// the path named by the injected flag, then returns a canned result.
+/// Panics when the tool did not inject the flag, pinning the injection itself.
+struct LogFileWritingLauncher {
+    content: &'static str,
+    result: LaunchResult,
+}
+
+impl Launcher for LogFileWritingLauncher {
+    fn run(
+        &self,
+        spec: &LaunchSpec,
+        _timeouts: Timeouts,
+        on_spawn: &mut dyn FnMut(u32),
+    ) -> Result<LaunchResult, Error> {
+        on_spawn(0);
+        assert_eq!(
+            spec.args.first().map(String::as_str),
+            Some("--log-file"),
+            "expected `--log-file` to be injected before the user args"
+        );
+        std::fs::write(&spec.args[1], self.content).unwrap();
+        Ok(self.result.clone())
+    }
+}
+
+#[test]
+fn force_killed_run_still_renders_from_pinned_log_file() {
+    // A force-killed jp prints no trace-path marker on stderr, but the log
+    // pinned via `--log-file` holds every event written up to the kill.
+    // The run must succeed from that file alone, with the force-kill banner.
+    let workspace = camino_tempfile::tempdir().unwrap();
+    let root = workspace.path();
+    let launcher = LogFileWritingLauncher {
+        content: "{\"timestamp\":\"2026-07-10T10:00:00.000Z\",\"level\":\"INFO\",\"fields\":{\"\
+                  message\":\"event before kill\"},\"target\":\"jp_cli\"}\n",
+        result: launched("no marker here\n", Termination::Forced),
+    };
+
+    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.contains("[!WARNING]"), "got:\n{content}");
+    assert!(content.contains("force-killed"), "got:\n{content}");
+    // The event came from the pinned log file, not the (absent) marker path.
+    assert!(content.contains("event before kill"), "got:\n{content}");
+}
+
 #[test]
 fn force_killed_without_marker_reports_note() {
     let workspace = camino_tempfile::tempdir().unwrap();

.config/jp/tools/src/debug_jp/util/launch.rs

@@ -14,7 +14,8 @@
 //! jp's own graceful shutdown, which flushes the trace log and the dhat heap
 //! profile.
 //! A wedged process is force-killed as a backstop (`SIGKILL` on Unix, job
-//! termination on Windows), which loses those artifacts.
+//! termination on Windows), which loses artifacts that require a clean exit
+//! (e.g. the dhat heap profile).
 //! How the process ended is reported in [`LaunchResult::termination`].
 
 use std::{
@@ -102,8 +103,8 @@ pub(crate) enum Termination {
     Graceful,
     /// Ignored the graceful-shutdown request and was force-killed (`SIGKILL` on
     /// Unix, job termination on Windows).
-    /// Artifacts that depend on a clean shutdown (trace log, heap profile) may
-    /// be missing.
+    /// Artifacts that depend on a clean shutdown (e.g. the dhat heap profile)
+    /// may be missing; incrementally written ones (the trace log) are partial.
     Forced,
 }
 

.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<TraceEvent> {
     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: <path>` when the output format is text,
+/// or a `{"trace_log": "<path>"}` 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<String> {
+    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<String> {
+    if let Some(path) = line.strip_prefix(TRACE_PATH_PREFIX) {
+        return Some(path.trim().to_owned());
+    }
+    match serde_json::from_str::<Value>(line).ok()? {
+        Value::Object(obj) => match obj.get("trace_log")? {
+            Value::String(path) => Some(path.clone()),
+            _ => None,
+        },
+        _ => None,
+    }
+}
+
 fn parse_line(line: &str) -> Option<TraceEvent> {
     if line.trim().is_empty() {
         return None;

.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.

.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: <path>` 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::<Vec<_>>()
         .join("\n")
 }