Add tracing spans and structured fields to Ninja subprocess execution

[coderabbitai]

Background

The NETSUKE_NINJA feature (PR #323) improved observability around Ninja subprocess execution. The following have already been implemented in PR #323:

• command_span creates a "ninja_subprocess" tracing span with stable low-cardinality fields: operation, ninja_program, redacted_arg_count, suppress_stderr, failure_category = field::Empty
• Spawn and exit failures record failure_category = "spawn" and failure_category = "exit_status" as structured span fields
• log_command_execution, log_command_spawn_failure, log_command_exit_failure emit structured tracing events with operation and ninja_program fields

Remaining required work

Two acceptance criteria from the original description remain unmet:

1. Log NETSUKE_NINJA resolution at the env-var boundary

resolve_ninja_program_utf8_with in src/runner/process/mod.rs silently picks the env-var value or falls back to NINJA_PROGRAM with no trace event. Add a debug! event at that boundary, e.g.:

fn resolve_ninja_program_utf8_with<F>(mut read_env: F) -> Utf8PathBuf
where
    F: FnMut(&str) -> Option<OsString>,
{
    match read_env(NINJA_ENV).and_then(|value| {
        Utf8PathBuf::from_path_buf(PathBuf::from(value)).ok()
    }) {
        Some(path) => {
            tracing::debug!(
                ninja_program = %path,
                source = "env",
                "Resolved Ninja program from {NINJA_ENV}"
            );
            path
        }
        None => {
            tracing::debug!(
                ninja_program = NINJA_PROGRAM,
                source = "default",
                "NETSUKE_NINJA unset or non-UTF-8; using default Ninja program"
            );
            Utf8PathBuf::from(NINJA_PROGRAM)
        }
    }
}

2. Demote high-cardinality args/paths from the log event message

log_command_execution currently emits the full redacted_command string (which includes the build file path and target list) in the message body. Move high-cardinality data to a debug! companion event rather than including it in the info! span event message. The info! event should carry only stable low-cardinality fields; the redacted_command string should be emitted separately at debug! level.

Acceptance criteria

• resolve_ninja_program_utf8_with emits a debug! event at the env-var resolution boundary with ninja_program and source fields
• log_command_execution no longer includes redacted_command in its info! message body; that string is emitted at debug! level instead
• Existing tests continue to pass under make check-fmt && make lint && make test
• No broad lint suppressions beyond narrowly scoped #[expect(..., reason = "...")]

Backlinks

• PR: Document Ninja executable override (#83) #323
• Issue: Support overriding Ninja executable via NETSUKE_NINJA #83
• Raised by: @leynos

[coderabbitai]

🔗 Related PRs

#302 - Overhaul Netsuke CLI documentation contract [merged]
#305 - Add Kani tooling and local smoke targets (4.1.1) [merged]
#308 - Add Kani smoke CI job (4.1.2) [merged]
#309 - Expand top-level action flow control (3.14.2) [merged]
leynos/mdtablefix#303 - Add observability for inline wrapping token classification (#296) [merged]

---

📝 Issue Planner

_{Check the box below or use the @coderabbitai plan command to generate an implementation plan and prompts that you can use with your favorite coding assistant.}

---

🧪 Issue enrichment is currently in open beta.

You can configure auto-planning by selecting labels in the issue_enrichment configuration.

To disable automatic issue enrichment, add the following to your .coderabbit.yaml:

issue_enrichment:
  auto_enrich:
    enabled: false

💬 Have feedback or questions? Drop into our discord!

[leynos]

@CodeRabbit plan

[coderabbitai]

Coding Plan

Summary

• Normalise the existing env-var resolution debug! events so the ninja_program and source fields appear on every branch, closing criterion #1 with minimal change.
• Split log_command_execution into an info! event with only low-cardinality structured fields and a debug! companion event that carries the redacted_command text.
• Preserve the exact "Executing command: {}" message on the debug! event so the --verbose (TRACE) integration assertions in tests/logging_stderr/verbose.rs pass without edits.
• Add targeted with_test_subscriber tests and update the developers' guide to document the new contract.

---

File-Level Change Summary

• src/runner/process/ninja_program.rs: normalise the four debug! calls in resolve_ninja_program_utf8_with to emit a ninja_program field on every branch beside source.
• src/runner/process/command_logging.rs: change log_command_execution to emit an info! event with a static low-cardinality message plus the stable fields, and add a debug! companion event carrying "Executing command: {}" with redacted_command.
• src/runner/process/tests.rs (and/or the command_logging.rs test module): add with_test_subscriber tests for the split events and the env-var resolution events.
• docs/developers-guide.md: update the command_logging section to describe the implemented companion-event split.
• tests/logging_stderr/verbose.rs: no change expected; verify it still passes.

Follow-up Agent Prompt

Implement the two acceptance criteria for Ninja subprocess tracing.

1. In src/runner/process/ninja_program.rs, normalise resolve_ninja_program_utf8_with so every debug! branch emits a `ninja_program` field alongside the existing `source` field. Keep the existing `source` values and messages. Do not change return values or the signature.

2. In src/runner/process/command_logging.rs, edit log_command_execution:
   - Give the info! event a static message (for example "Executing Ninja subprocess") and drop the redacted_command interpolation. Keep the fields operation, ninja_program, arg_count, env_override_count, path_overridden, suppress_stderr.
   - Add a debug! event with the message "Executing command: {}" interpolating context.redacted_command, plus operation and ninja_program fields. Leave the failure loggers and command_span unchanged.

3. Add tracing tests with crate::test_tracing_capture::with_test_subscriber:
   - INFO level: assert the info! event does not contain "Executing command".
   - DEBUG level: assert the debug! event contains "Executing command:" and the redacted command text.
   - DEBUG level: assert resolve_ninja_program_utf8_with emits ninja_program and source fields on override and fallback branches, using the existing MockEnv ninja_env fixture.

4. Update docs/developers-guide.md command_logging section to describe the split; remove the "future work under `#384`" framing.

5. Run `make check-fmt && make lint && make test`. Use only narrowly scoped #[expect(..., reason = "...")] if a lint suppression is unavoidable. Do not edit tests/logging_stderr/verbose.rs; confirm it still passes because --verbose maps to TRACE and the debug! event keeps the "Executing command: {}" text.

Design Choices

Design Choice 1: How to emit `redacted_command` at `debug!` level?

Options Considered:

1. Emit redacted_command as a structured field on the new debug! event with a fresh static message. This changes the rendered stderr text and breaks the verbose.rs literal assertions.
2. Keep the exact "Executing command: {}" message on the new debug! event, interpolating redacted_command. The rendered text is unchanged, so verbose.rs passes without edits.

Chosen Option: 2

Rationale: It preserves the observable --verbose output and the existing literal assertions while still meeting the requirement that the string leaves the info! event. The ticket states the string must move to debug!. It does not fix the event shape. The existing tests/logging_stderr/verbose.rs asserts the literal text "Executing command: {ninja_stem} " in --verbose stderr, and --verbose maps to LevelFilter::TRACE, which still admits debug! events.

Design Choice 2: Does criterion `#1` require code changes?

Options Considered:

1. Leave the function unchanged and treat criterion #1 as satisfied.
2. Normalise the field naming so every branch emits a ninja_program field alongside source, making the acceptance criterion unambiguously met on all branches.

Chosen Option: 2

Rationale: A small, low-risk normalisation guarantees the criterion is met uniformly. Retain the existing source values ("fallback" and the NINJA_ENV constant) documented in ADR-008 rather than the ticket's illustrative "env"/"default" values. The exploration confirms resolve_ninja_program_utf8_with already emits a debug! event on every branch. Two branches use the field name ninja_program; the fallback branches use fallback_program / configured_ninja.

💡 User Tips

Regenerate the plan with different choices with @coderabbitai <feedback>.

Implementation Steps

Phase 1: Finalise NETSUKE_NINJA env-var boundary tracing

Confirm the env-var resolution boundary emits a debug! event on every branch, and normalise the field naming so the ninja_program field sits next to source on all branches. This closes acceptance criterion #1 without disturbing the resolver's return values or the mockable::Env seam.

Normalise env-var resolution debug fields

Make the ninja_program field appear on every resolution branch.

• Update src/runner/process/ninja_program.rs so each debug! call in resolve_ninja_program_utf8_with emits a ninja_program field alongside the existing source field.
• Rename the fallback branches' fallback_program field to ninja_program so the field name is stable across all four branches.
• Retain the non-UTF-8 branch's configured_ninja diagnostic field, and add the ninja_program field for the resolved fallback value.
• Keep the existing source values ("fallback" and the NINJA_ENV constant) and the existing human-readable messages. Do not change the return values or the function signature.

🤖 Prompt for AI agents

Implement Phase 1: finalise NETSUKE_NINJA env-var boundary tracing. The goal is
to guarantee a stable `ninja_program` field on every `debug!` branch of the
resolver, closing acceptance criterion `#1`.

- Open `src/runner/process/ninja_program.rs` and locate
`resolve_ninja_program_utf8_with`.
- Update each of the four `debug!` calls so every branch emits a `ninja_program`
field alongside the existing `source` field.
- Rename the fallback branches' `fallback_program` field to `ninja_program` for
naming consistency across all branches.
- Keep the non-UTF-8 branch's `configured_ninja` diagnostic field intact, and
add the `ninja_program` field carrying the resolved fallback value.
- Do not change the existing `source` values (`"fallback"` and the `NINJA_ENV`
constant) or the existing human-readable messages.
- Do not change the function's return values or signature.

Phase 2: Split command execution logging

Separate the stable structured fields from the high-cardinality command string. The info! event keeps only low-cardinality fields. A new debug! companion event carries the redacted command text. Both events fire inside the ninja_subprocess span, so they correlate through the span context.

Move the redacted command to a debug companion event

Remove the high-cardinality payload from the info! event message.

• Update log_command_execution in src/runner/process/command_logging.rs.
• Change the info! event message to a static, low-cardinality string (for example "Executing Ninja subprocess"), and remove the context.redacted_command interpolation from that event.
• Keep the info! event's existing structured fields: operation, ninja_program, arg_count, env_override_count, path_overridden, and suppress_stderr.
• Add a new debug! event within the same function. Emit the message "Executing command: {}" interpolating context.redacted_command, and include the operation and ninja_program fields for correlation.
• Do not expose the private redacted_command field outside the module; both events already run inside command_logging.rs, so no field visibility change is needed.
• Leave log_command_spawn_failure, log_command_exit_failure, and command_span unchanged.

🤖 Prompt for AI agents

Implement Phase 2: split command execution logging. The goal is to separate
stable low-cardinality fields (info! level) from the high-cardinality redacted
command string (debug! level companion event), correlated via the existing
`ninja_subprocess` span.

- Edit `log_command_execution` in `src/runner/process/command_logging.rs`.
- Change the `info!` event message to a static, low-cardinality string (for
example `"Executing Ninja subprocess"`), and remove the
`context.redacted_command` interpolation from that event.
- Keep the `info!` event's existing structured fields: `operation`,
`ninja_program`, `arg_count`, `env_override_count`, `path_overridden`,
`suppress_stderr`.
- Add a new `debug!` event in the same function with the message `"Executing
command: {}"`, interpolating `context.redacted_command`, and include `operation`
and `ninja_program` fields for correlation.
- Do not change the visibility of the `redacted_command` field; both events
remain inside `command_logging.rs`.
- Leave `log_command_spawn_failure`, `log_command_exit_failure`, and
`command_span` unchanged.

Phase 3: Test coverage and documentation

Add focused tracing tests for both criteria, and update the developers' guide to describe the new companion-event contract.

Task 1: Add tracing assertions for the new events

Prove both events behave as required.

• Add unit tests in src/runner/process/tests.rs (or the colocated #[cfg(test)] mod tests in command_logging.rs, matching the nearest existing convention) using crate::test_tracing_capture::with_test_subscriber.
• Add a test at LevelFilter::INFO that asserts the info! event does not contain "Executing command" and does contain the low-cardinality fields.
• Add a test at LevelFilter::DEBUG that asserts the debug! companion event contains "Executing command:" with the redacted command text.
• Add a test at LevelFilter::DEBUG around resolve_ninja_program_utf8_with (composed with the existing MockEnv ninja_env fixture) that asserts the resolution debug! event contains ninja_program and source fields for the override and fallback branches.
• Verify tests/logging_stderr/verbose.rs still passes unchanged; the --verbose (TRACE) path still renders the "Executing command: {ninja_stem} " text from the new debug! event.

Task 2: Update the developers' guide

Record the implemented companion-event contract.

• Update the runner::process::command_logging section of docs/developers-guide.md (around lines 3434–3446).
• Describe that the info! execution event now carries only stable fields, and that the redacted command string is emitted on a debug! companion event.
• Remove or amend the note that frames this change as future work under issue #384, since the split is now implemented.

🤖 Prompt for AI agents

Implement Phase 3: test coverage and documentation. The goal is to prove both
acceptance criteria through tracing tests, and to document the implemented
companion-event contract.

- Add unit tests in `src/runner/process/tests.rs` (or the colocated
`#[cfg(test)] mod tests` in `command_logging.rs`, matching the nearest existing
convention), using `crate::test_tracing_capture::with_test_subscriber`.
- Add a test at `LevelFilter::INFO` asserting the `info!` event does not contain
`"Executing command"` and does contain the low-cardinality fields.
- Add a test at `LevelFilter::DEBUG` asserting the `debug!` companion event
contains `"Executing command:"` with the redacted command text.
- Add a test at `LevelFilter::DEBUG` around `resolve_ninja_program_utf8_with`,
composed with the existing `MockEnv` `ninja_env` fixture, asserting the
resolution `debug!` event contains `ninja_program` and `source` fields for the
override and fallback branches.
- Verify `tests/logging_stderr/verbose.rs` still passes unchanged, since the
`--verbose` (`TRACE`) path still renders `"Executing command: {ninja_stem} "`
from the new `debug!` event.
- Update the `runner::process::command_logging` section of
`docs/developers-guide.md` (around lines 3434–3446) to describe that the `info!`
event now carries only stable fields, and that the redacted command string moves
to a `debug!` companion event.
- Remove or amend the note that frames this change as future work under issue
`#384`, since the split is now implemented.

Research

The runner's Ninja subprocess logging lives under src/runner/process/. ninja_program.rs owns resolve_ninja_program_utf8_with, which selects the NETSUKE_NINJA override or falls back to NINJA_PROGRAM. command_logging.rs owns CommandLogContext, the command_span function, and the three log_command_* helpers. redaction.rs produces the redacted argument list. Tracing tests use crate::test_tracing_capture::with_test_subscriber, filtered by LevelFilter. End-to-end log assertions live in tests/logging_stderr/verbose.rs. The exploration shows the env-var branch is already largely instrumented, so the substantial new work is the logging split in command_logging.rs.

---

🚀 Next Steps

🤖 All AI agent prompts combined

Task: 1

Implement Phase 1: finalise NETSUKE_NINJA env-var boundary tracing. The goal is
to guarantee a stable `ninja_program` field on every `debug!` branch of the
resolver, closing acceptance criterion `#1`.

- Open `src/runner/process/ninja_program.rs` and locate
`resolve_ninja_program_utf8_with`.
- Update each of the four `debug!` calls so every branch emits a `ninja_program`
field alongside the existing `source` field.
- Rename the fallback branches' `fallback_program` field to `ninja_program` for
naming consistency across all branches.
- Keep the non-UTF-8 branch's `configured_ninja` diagnostic field intact, and
add the `ninja_program` field carrying the resolved fallback value.
- Do not change the existing `source` values (`"fallback"` and the `NINJA_ENV`
constant) or the existing human-readable messages.
- Do not change the function's return values or signature.
===============================================================================

Task: 2

Implement Phase 2: split command execution logging. The goal is to separate
stable low-cardinality fields (info! level) from the high-cardinality redacted
command string (debug! level companion event), correlated via the existing
`ninja_subprocess` span.

- Edit `log_command_execution` in `src/runner/process/command_logging.rs`.
- Change the `info!` event message to a static, low-cardinality string (for
example `"Executing Ninja subprocess"`), and remove the
`context.redacted_command` interpolation from that event.
- Keep the `info!` event's existing structured fields: `operation`,
`ninja_program`, `arg_count`, `env_override_count`, `path_overridden`,
`suppress_stderr`.
- Add a new `debug!` event in the same function with the message `"Executing
command: {}"`, interpolating `context.redacted_command`, and include `operation`
and `ninja_program` fields for correlation.
- Do not change the visibility of the `redacted_command` field; both events
remain inside `command_logging.rs`.
- Leave `log_command_spawn_failure`, `log_command_exit_failure`, and
`command_span` unchanged.
===============================================================================

Task: 3

Implement Phase 3: test coverage and documentation. The goal is to prove both
acceptance criteria through tracing tests, and to document the implemented
companion-event contract.

- Add unit tests in `src/runner/process/tests.rs` (or the colocated
`#[cfg(test)] mod tests` in `command_logging.rs`, matching the nearest existing
convention), using `crate::test_tracing_capture::with_test_subscriber`.
- Add a test at `LevelFilter::INFO` asserting the `info!` event does not contain
`"Executing command"` and does contain the low-cardinality fields.
- Add a test at `LevelFilter::DEBUG` asserting the `debug!` companion event
contains `"Executing command:"` with the redacted command text.
- Add a test at `LevelFilter::DEBUG` around `resolve_ninja_program_utf8_with`,
composed with the existing `MockEnv` `ninja_env` fixture, asserting the
resolution `debug!` event contains `ninja_program` and `source` fields for the
override and fallback branches.
- Verify `tests/logging_stderr/verbose.rs` still passes unchanged, since the
`--verbose` (`TRACE`) path still renders `"Executing command: {ninja_stem} "`
from the new `debug!` event.
- Update the `runner::process::command_logging` section of
`docs/developers-guide.md` (around lines 3434–3446) to describe that the `info!`
event now carries only stable fields, and that the redacted command string moves
to a `debug!` companion event.
- Remove or amend the note that frames this change as future work under issue
`#384`, since the split is now implemented.

💡 Iterate on the plan with: `@coderabbitai` <feedback>

Example Feedback
- `@coderabbitai` You can skip phase 3. Add a simple unit test case for phase 2.
- `@coderabbitai` For design choice 1 go ahead with option 3 and replan.

---

💬 Have feedback or questions? Drop into our discord!