Skip to content

feat(log): split -vv output into trace.log + output.log, drop -vvv - #2201

Merged
max-sixty merged 5 commits into
mainfrom
vv-output
Apr 13, 2026
Merged

feat(log): split -vv output into trace.log + output.log, drop -vvv#2201
max-sixty merged 5 commits into
mainfrom
vv-output

Conversation

@max-sixty

Copy link
Copy Markdown
Owner

Motivation

At -vv, raw subprocess bodies were bounded (200 lines / 64 KB) on both stderr and verbose.log, with full output only available by rerunning at -vvv. Large captures (notably git log -p piped into patch-id during wt list) would routinely flood stderr with elision markers and force a second run just to see what was elided.

Change

The verbosity map is now -v (info) and -vv (debug); any -v count above 2 collapses to -vv. Captured subprocess stdout/stderr fan out through two log targets in src/shell_exec.rs:

  • SUBPROCESS_TERMINAL_TARGET → bounded preview on stderr, mirrored to .git/wt/logs/trace.log (new, replaces verbose.log)
  • SUBPROCESS_FULL_TARGET → uncapped body to .git/wt/logs/output.log (new), never stderr

src/log_files.rs (renamed from src/verbose_log.rs) owns both file sinks behind a LogSink type and a route(target) helper that is the single source of truth for sink selection. src/main.rs's env_logger format closure matches on the Route enum and emits once per sink. Diagnostic reports embed trace.log and reference output.log by path — multi-MB raw bodies would swamp a bug report.

Fallback path

When RUST_LOG=debug is set without -vv, neither sink is active. FULL records drop and the TERMINAL preview reaches stderr as before — preserving the bounded-stderr guarantee. The elision marker phrases its hint based on whether output.log was opened, so users in the fallback path see rerun with -vv for full output rather than a pointer to a file that doesn't exist.

Key files

  • src/log_files.rs — new module; LogSink, TRACE, OUTPUT, route.
  • src/shell_exec.rs — two pub const targets, log_output emits on both, elision hint switches on OUTPUT_LOG_AVAILABLE.
  • src/main.rs — verbosity map + format closure.
  • src/diagnostic.rs — template splits inlined trace.log from referenced output.log.
  • src/commands/config/state.rs — diagnostic file recognition for the new names.

Testing

  • test_vv_splits_full_and_bounded_output[wt-trace] in trace.log, raw stdout in output.log, no trace records in output.log.
  • test_vv_bounded_on_stderr_full_in_output_log — 250-ref packed-refs trip the elision cap; asserts the marker on stderr + trace.log, full content in output.log without elision.
  • test_rust_log_debug_fallback_without_vv — no log files created at -v 0 + RUST_LOG=debug; bounded preview reaches stderr.

This was written by Claude Code on behalf of max-sixty

At `-vv`, raw subprocess bodies used to be bounded (200 lines / 64 KB) on both stderr and `verbose.log`, with full output only available by rerunning at `-vvv`. Large captures (`git log -p` piped into `patch-id`) would routinely flood stderr with elision markers and force a second run.

The verbosity map is now `-v` (info) and `-vv` (debug); any `-v` count above 2 collapses to `-vv`. Captured subprocess stdout/stderr fan out through two log targets in `src/shell_exec.rs`:

- `SUBPROCESS_TERMINAL_TARGET` → bounded preview on stderr, mirrored to `.git/wt/logs/trace.log` (new, replaces `verbose.log`)
- `SUBPROCESS_FULL_TARGET` → uncapped body to `.git/wt/logs/output.log` (new), never stderr

`src/log_files.rs` (renamed from `src/verbose_log.rs`) owns both file sinks behind a `LogSink` type and a `route(target)` helper that is the single source of truth for sink selection. `src/main.rs`'s env_logger format closure matches on the `Route` enum and emits once per sink. Diagnostic reports embed `trace.log` and reference `output.log` by path (multi-MB raw bodies would swamp a bug report).

When `RUST_LOG=debug` is set without `-vv`, neither sink is active. `FULL` records drop and the `TERMINAL` preview reaches stderr as before — preserving the bounded-stderr guarantee. The elision marker phrases its hint based on whether `output.log` was opened.

Co-Authored-By: Claude <noreply@anthropic.com>

@worktrunk-bot worktrunk-bot left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A couple of stale verbose.log references were missed by the rename. Both fall outside the diff hunks, so I can't post them as inline suggestions — happy to push a fix commit if you'd like.

docs/content/faq.md line 120 — the "files Worktrunk creates" table still lists verbose.log as the -vv output. Suggested:

| `.git/wt/logs/trace.log` | Debug log mirroring stderr (commands, `[wt-trace]` records, bounded subprocess previews) | Running with `-vv` |
| `.git/wt/logs/output.log` | Raw uncapped subprocess stdout/stderr bodies | Running with `-vv` |

skills/worktrunk/reference/faq.md:113 is the auto-synced mirror — test_command_pages_and_skill_files_are_in_sync will regenerate it once the source is updated.

tests/integration_tests/diagnostic.rs lines 535–557test_v_does_not_write_log_files still asserts on wt_logs.join("verbose.log"). The test passes because that file is never created, but it isn't actually guarding the new paths. Suggested:

/// `-vv` is the threshold for `trace.log`, `output.log`, and `diagnostic.md`.
#[rstest]
fn test_v_does_not_write_log_files(repo: TestRepo) {
    let output = repo.wt_command().args(["list", "-v"]).output().unwrap();
    assert!(output.status.success(), "Command should succeed");

    let wt_logs = repo.root_path().join(".git").join("wt/logs");
    assert!(
        !wt_logs.join("diagnostic.md").exists(),
        "Diagnostic file should NOT be created with just -v"
    );
    for name in ["trace.log", "output.log"] {
        assert!(
            !wt_logs.join(name).exists(),
            "{name} should NOT be created with just -v (requires -vv)"
        );
    }
}

The split itself reads cleanly — log_files::route keeps sink selection in one place, the OUTPUT_LOG_AVAILABLE gate keeps the elision marker honest, and the new tests (test_vv_splits_full_and_bounded_output, test_vv_bounded_on_stderr_full_in_output_log, test_rust_log_debug_fallback_without_vv) cover the three interesting routing cases.

@worktrunk-bot

Copy link
Copy Markdown
Collaborator

CI failed on Windows: test_diagnostic_report_file_format snapshot diff at the new Raw subprocess output section.

60 │ <details>
61 │ <summary>Raw subprocess output</summary>
62 │
63 │-Full captured stdout/stderr is in `_REPO_/.git/wt/logs/output.log` — not inlined because it can be multi-MB.
63 │+Full captured stdout/stderr is in `[REPO_PATH] — not inlined because it can be multi-MB.
64 │ </details>

Cause: in src/diagnostic.rs the new output_log_path is rendered with the OS-native separator (\ on Windows). normalize_report's generic Windows-path regex [A-Z]:[^\s)]+ then greedily eats through the closing backtick and rewrites the whole thing to [REPO_PATH], while the snapshot expects the existing _REPO_/... style for known wt-logs paths.

Per CLAUDE.md ("Path normalization | path_slash::PathExt::to_slash_lossy()"), the cleanest fix is on the production side — render the bug-report path with forward slashes so it's also readable when a Windows user pastes it into an issue:

use path_slash::PathExt as _;

let output_log_path = crate::log_files::OUTPUT
    .path()
    .map(|p| p.to_slash_lossy().into_owned());

That alone makes the snapshot pass on all three platforms; no test change required. (Linux/macOS are already at /, so behavior is unchanged there.)

Happy to push the one-liner if you'd like.

max-sixty and others added 2 commits April 13, 2026 10:02
codecov/patch flagged `LogSink::new` uncovered because const fn calls at
static initialization don't emit runtime coverage events. Inline the struct
construction into the `TRACE` / `OUTPUT` statics and drop the helper.

Co-Authored-By: Claude <noreply@anthropic.com>
- Update FAQ's "files worktrunk creates" table: split verbose.log into
  trace.log (mirrors stderr) and output.log (raw subprocess bodies).
- Update test_v_does_not_write_log_files to assert the new file names.
- Tighten the diagnostic-snapshot path regex so inlined Windows paths
  in the new "Raw subprocess output" <details> section don't eat the
  closing backtick (the greedy [^\s)]+ was swallowing the end of
  code-span wrappers on Windows).

Co-Authored-By: Claude <noreply@anthropic.com>
worktrunk-bot
worktrunk-bot previously approved these changes Apr 13, 2026
@worktrunk-bot
worktrunk-bot dismissed their stale review April 13, 2026 17:25

CI failed on Windows — the regex tightening didn't fix the snapshot diff (analysis follows).

@worktrunk-bot worktrunk-bot left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The Windows snapshot diff isn't actually fixed — test_diagnostic_report_file_format failed again on the Windows runner with the same shape as before:

-Full captured stdout/stderr is in `_REPO_/.git/wt/logs/output.log` — not inlined because it can be multi-MB.
+Full captured stdout/stderr is in `[REPO_PATH]` — not inlined because it can be multi-MB.

The backtick exclusion in the regex closes one hole (the closing backtick is no longer eaten) but doesn't address the underlying mismatch. Walking through what happens on Windows:

  1. Production renders the path with backslashes: D:\a\worktrunk\worktrunk\.tmpXXX\repo\.git\wt\logs\output.log.
  2. normalize_report runs first and the [A-Z]:[^\s)+`]+branch greedily matches the whole path →[REPO_PATH]`.
  3. The insta _REPO_ filter (tests/common/mod.rs:597) then has nothing left to substitute, so the snapshot ends with [REPO_PATH] instead of _REPO_/.git/wt/logs/output.log.

The Unix branch happens to escape this because it requires /repo\. (a literal repo. segment), so the main repo path …/repo/.git/... doesn't match and the insta filter gets first crack at it. The Windows branch has no such anchor.

Two fixes that would actually work:

(a) Render with forward slashes in production (my earlier suggestion, and what CLAUDE.md calls out for path-display normalization):

use path_slash::PathExt as _;

let output_log_path = crate::log_files::OUTPUT
    .path()
    .map(|p| p.to_slash_lossy().into_owned());

at src/diagnostic.rs:166-168. The path becomes D:/a/.../repo/.git/wt/logs/output.log, which matches neither branch of the normalize_report regex (no repo. segment), so the insta _REPO_ filter substitutes it cleanly and the snapshot matches as on Linux/macOS. Bonus: Windows users pasting the path into a bug report get the readable forward-slash form.

(b) Anchor the Windows regex the same way the Unix one is anchored — only match when the path actually contains a repo.<something> segment:

result = regex::Regex::new(r"([A-Z]:[^\s)`]+\\repo\.[^\s)`]+|/[^\s)`]+/repo\.[^\s)`]+)")

(a) is cleaner — it fixes the production-side oddity that motivated the test failure in the first place, rather than just teaching the test to look the other way.

Happy to push (a) if you'd like.

On Windows the path embedded in the `Raw subprocess output` section
contained backslashes. The insta prefix filter replaced `D:\...\repo`
with `_REPO_`, leaving `_REPO_\.git\wt\logs\output.log` — at which
point the snapshot normalizer's drive-letter fallback matched the
remainder and collapsed it to `[REPO_PATH]`, eating the closing
backtick.

Emit the path with `path_slash::to_slash_lossy` so the markdown line
reads the same on every platform.

Co-Authored-By: Claude <noreply@anthropic.com>
The `[A-Z]:[^\s)\`]+` branch matched any drive-letter path greedily,
including the main TestRepo root. On Windows that caused the output.log
path in the diagnostic report's `Raw subprocess output` section to be
replaced with `[REPO_PATH]` in its entirety — before insta's prefix
filter could rewrite just the repo root to `_REPO_/`.

Require the `\repo.<name>` or `/repo.<name>` segment in both branches
so only worktree paths match. The main repo path (`.../repo` with no
dot) falls through to insta's prefix filter, which yields the expected
`_REPO_/.git/wt/logs/output.log` form consistent with Linux/macOS.

Co-Authored-By: Claude <noreply@anthropic.com>
@max-sixty
max-sixty merged commit 3e1b351 into main Apr 13, 2026
25 checks passed
@max-sixty
max-sixty deleted the vv-output branch April 13, 2026 17:50
worktrunk-bot added a commit that referenced this pull request Apr 14, 2026
…rename

Two stale references from #2201 (verbose.log → trace.log split) and
#2209 (git-common-dir caching):

- Replace `VERBOSE_LOG` with `TRACE`/`OUTPUT` (the two log sinks that
  replaced it) in the process-level singletons list in `src/git/
  repository/mod.rs`, and add `GIT_COMMON_DIR_CACHE` which was added
  in #2209 but missed in the inventory.
- Rename `test_diagnostic_verbose_log_contains_git_commands` to
  `test_diagnostic_trace_log_contains_git_commands` in `tests/
  integration_tests/diagnostic.rs` — the assertions already target
  the "Trace log" section. Rename local bindings for consistency.

Pure documentation/test-naming cleanup; no behavioral change.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
max-sixty added a commit that referenced this pull request May 25, 2026
…2892)

## Motivation

`wt … -vv` produced ~15K lines of stderr per invocation — unreadable in
scrollback, forced redirect to a file, at which point the parallel
`trace.log` mirror introduced by #2201 was redundant noise. The earlier
split (#2201) only file-routed the *uncapped raw subprocess bodies*
(`SUBPROCESS_FULL_TARGET`); everything else — `$ cmd` headers,
`[wt-trace]` spans, bounded subprocess previews — stayed on stderr.

## Change

At `-vv`, the `log::*` pipeline routes to `.git/wt/logs/trace.log`
instead of stderr. A one-line startup pointer on stderr tells the user
where it went:

```
○ Tracing to ~/.../trace.log (raw subprocess output @ ~/.../output.log)
```

User-facing `eprintln!` output (status messages, template expansions,
hints) is **unaffected** — it stays on stderr at every verbosity level.
This change governs only the `log::*` macro pipeline.

`-v` is unchanged (Info on stderr, no file). `RUST_LOG=debug` without
`-vv` is unchanged (Debug on stderr, no file — the documented fallback
from #2201).

Result on `wt list -vv`: stderr 15K → 3 lines. `trace.log` gets the full
~1K-line debug trace as before.

## Implementation notes for review

- `src/log_files.rs::route()` is now the only place that picks the sink.
Non-`FULL` targets go to `File(&TRACE)` when `TRACE.is_active()`, else
`Stderr`. Format closure in `src/main.rs` simplified to a `match route`
— no more "mirror to TRACE then write to stderr" branch.
- `Repository::current()` is primed *before* `env_logger.init()` so the
rev-parse fired by `log_files::init` is a memory-cache hit. Records
emitted during priming go to a not-yet-installed logger and are dropped
— robust against future `Repository::current` emissions. A `Ctrl-C`
during the ~5ms priming window can leak one `$ git rev-parse` line;
documented inline, cheaper than violating "all commands through `Cmd`".
- `announce_trace_destination()` handles the rare split-init case where
`output.log` open fails (path-type mismatch, fs quota) but `trace.log`
succeeds — partial pointer + "output.log unavailable" hint. New
regression test `test_vv_pointer_handles_split_init` reproduces the
failure with a pre-existing directory at the `output.log` path.
- `SUBPROCESS_TERMINAL_TARGET` → `SUBPROCESS_BOUNDED_TARGET`. The
"terminal-safe" framing no longer fits now that the bounded preview
lives in `trace.log` rather than stderr.
- `diagnostic.md` doc cutover: three surfaces (`src/diagnostic.rs`,
`src/cli/config.rs`, `docs/content/faq.md`) still claimed "written when
warnings occur" — the code has no warning gate and writes on every
`-vv`. Docs cut over to match reality.

## Deferred follow-ups

Surfaced during review but out of scope here:

- **Unify `trace.log` + `output.log`** — the bounded preview at `-vv`
duplicates a subset of `output.log`'s uncapped bytes. The dual-file
design was explicitly approved for this PR; a follow-up could collapse
them with `diagnostic.md` doing the bounding at extraction time.
- **`RUST_LOG` precedence at `-v`** — pre-existing: `-v 0` honors
`RUST_LOG`, `-v` and `-vv` hardcode the level. Needs a policy decision
(always-honor / always-ignore / merge) more than a cleanup.
- **`tracing` crate migration** — deserves its own dedicated PR with
`[wt-trace]` migration as the headline.

## Tests

3822 tests pass (+1 regression). Notable changes:

- `test_vv_bounded_on_stderr_full_in_output_log` →
`test_vv_log_pipeline_silent_on_stderr` — inverted assertions (marker
must NOT appear on stderr; must appear in `trace.log`). Added a
stderr-pointer presence check.
- `test_vv_pointer_handles_split_init` — new; reproduces the split-init
asymmetry by creating a directory at `output.log`'s path, asserts the
partial pointer fires and `trace.log` still works.

> _This was written by Claude Code on behalf of max-sixty_

---------

Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
max-sixty added a commit that referenced this pull request May 26, 2026
… on stderr (#2913)

## Motivation

The `-v` / `-vv` UX had three small issues that compounded:

1. **`output.log` is misnamed.** It holds the *uncapped raw
stdout/stderr of every subprocess `wt` spawns* — multi-MB possible (`git
log -p`, patch-id pipelines, etc.). "output" reads as "stuff `wt`
printed" — the small thing — when it's actually the big thing. Easy to
misread.
2. **`-vv` went fully dark on stderr.** PR #2892 moved the noisy debug
pipeline to files at `-vv`; in the process, the stderr layer was
disabled entirely. Users running `-vv` to see hook output (info-level,
which `-v` shows on stderr) suddenly couldn't.
3. **`-v` help text was a 150-char one-liner** packed into a
parenthetical, and the surrounding docs leaned on a "stderr stays
readable / `log::*` pipeline" framing that was Rust-jargon-flavored and
implied stderr-quiet at `-vv` — which is no longer true after change #2.

## Change

- **Rename `output.log` → `subprocess.log`.** Filename now matches
content. `OUTPUT` static → `SUBPROCESS`, plus the related
`OutputMakeWriter` / `OutputFileFormat` / `build_output_layer` symbol
renames.
- **`-vv` keeps the Info baseline on stderr.** `build_stderr_layer` no
longer returns `None` at `-vv`; debug-level records still route to file
layers only, so the terminal stays readable while info-level status
(hook output, template variables, the `Tracing to ...` pointer) shows
the same as at `-v`.
- **`-v` help text rewritten** to describe both levels cleanly without a
wall of detail.
- **`docs/content/faq.md` gets a "What does -v / -vv do?" section** with
a three-level table.
- **Docs cleanup**: drop "stderr stays readable" / `log::*` jargon /
"but not subprocess.log" negative framing from user-facing prose.

## Notes for review

- The only `log::info!` site in the codebase is
`commands/picker/mod.rs:389` (a single picker error message), so making
`-vv` show info-level on stderr doesn't add meaningful noise.
- `test_vv_log_pipeline_silent_on_stderr` is renamed to
`test_vv_debug_pipeline_silent_on_stderr` — its assertions only check
debug-level records stay out of stderr (they do); the old name implied
the whole `log::*` pipeline was silent, which was never quite true
(direct `eprintln!` always showed) and is less true now (info-level
routes to stderr).
- 67 of the 69 changed files are snapshot updates (help text and one
diagnostic snapshot) and auto-synced doc/skill mirrors. `git diff --stat
-- 'tests/snapshots/*' 'docs/content/*' 'skills/worktrunk/reference/*' |
tail -1` separates them.
- CHANGELOG: not touched. The historical entry that introduced
`output.log` (`#2201`) stays accurate for its release; this rename gets
a new line in the next release.

## Tests

3870 tests pass. Re-snapshotted all `test_help_*` snapshots, three
`step_alias` snapshots that quote the global help, and the diagnostic
file format snapshot.

> _This was written by Claude Code on behalf of max-sixty_

Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants