From b0dca3f77d09ef20cc206f70d2220214d89352c9 Mon Sep 17 00:00:00 2001 From: leynos Date: Tue, 9 Jun 2026 21:46:39 +0200 Subject: [PATCH 1/8] Stop double-logging external command invocations Every external command was logged twice: once at INFO by subprocess_runner via log_command_invocation, and again at DEBUG by invoke_via_subprocess via _log_subprocess_spawn, with two different renderings of the same command line. Keep the INFO-level record (it is the operationally visible one and already includes the working directory) and delete the redundant DEBUG spawn line. The DEBUG record for environment overrides is retained because it carries information the INFO line does not. Add regression tests pinning that a command produces exactly one invocation log record, at INFO, with and without a cwd. Closes #104 --- lading/runtime/subprocess_runner.py | 17 ++--- tests/unit/test_subprocess_runner_logging.py | 69 ++++++++++++++++++++ 2 files changed, 73 insertions(+), 13 deletions(-) create mode 100644 tests/unit/test_subprocess_runner_logging.py diff --git a/lading/runtime/subprocess_runner.py b/lading/runtime/subprocess_runner.py index 06a655c9..72f24ece 100644 --- a/lading/runtime/subprocess_runner.py +++ b/lading/runtime/subprocess_runner.py @@ -14,7 +14,7 @@ from pathlib import Path from lading.exceptions import LadingError -from lading.utils.process import format_command, log_command_invocation +from lading.utils.process import log_command_invocation _LOGGER = logging.getLogger(__name__) @@ -190,7 +190,9 @@ def invoke_via_subprocess( """ command = (program, *args) - _log_subprocess_spawn(command, context.cwd) + # The command line itself is logged once, at INFO, by + # ``subprocess_runner`` via ``log_command_invocation``; only the + # environment overrides are worth an extra DEBUG record here. _log_subprocess_environment(context.env) normalised_env = normalise_environment(context.env) process = _spawn_process(program, command, context, normalised_env) @@ -343,17 +345,6 @@ def _format_thread_name(program: str, stream: str) -> str: return f"lading-cmd-{safe}-{stream}" -def _log_subprocess_spawn( - command: cabc.Sequence[str], cwd: Path | None -) -> None: # pragma: no cover - logging only - """Log the rendered subprocess command and optional working directory.""" - rendered = format_command(command) - if cwd is None: - _LOGGER.debug("Spawning subprocess: %s", rendered) - else: - _LOGGER.debug("Spawning subprocess: %s (cwd=%s)", rendered, cwd) - - def _log_subprocess_environment(env: cabc.Mapping[str, str] | None) -> None: """Log redacted environment overrides for subprocess execution.""" if not env: diff --git a/tests/unit/test_subprocess_runner_logging.py b/tests/unit/test_subprocess_runner_logging.py new file mode 100644 index 00000000..5ca448ea --- /dev/null +++ b/tests/unit/test_subprocess_runner_logging.py @@ -0,0 +1,69 @@ +"""Regression tests for subprocess runner invocation logging. + +Issue #104: every external command used to be logged twice — once at INFO +by ``subprocess_runner`` and once at DEBUG by ``invoke_via_subprocess``. +These tests pin the single-log contract. +""" + +from __future__ import annotations + +import logging +import typing as typ + +from lading.runtime.subprocess_runner import subprocess_runner + +if typ.TYPE_CHECKING: + from pathlib import Path + + import pytest + + LogCaptureFixture = pytest.LogCaptureFixture +else: # pragma: no cover - typing helpers + Path = typ.Any + LogCaptureFixture = typ.Any + +_RUNNER_LOGGER = "lading.runtime.subprocess_runner" + + +def _invocation_records( + caplog: LogCaptureFixture, +) -> list[logging.LogRecord]: + """Return records that render the external command line.""" + return [ + record + for record in caplog.records + if "Running external command" in record.getMessage() + or "Spawning subprocess:" in record.getMessage() + ] + + +def test_command_logged_exactly_once(caplog: LogCaptureFixture) -> None: + """A command produces a single invocation log record at INFO.""" + caplog.set_level(logging.DEBUG, logger=_RUNNER_LOGGER) + + exit_code, stdout, stderr = subprocess_runner(("echo", "hello"), echo_stdout=False) + + assert exit_code == 0 + assert stdout.strip() == "hello" + assert stderr == "" + records = _invocation_records(caplog) + assert len(records) == 1 + assert records[0].levelno == logging.INFO + assert "Running external command: echo hello" in records[0].getMessage() + + +def test_command_logged_exactly_once_with_cwd( + caplog: LogCaptureFixture, tmp_path: Path +) -> None: + """The single invocation record includes the working directory.""" + caplog.set_level(logging.DEBUG, logger=_RUNNER_LOGGER) + + exit_code, _, _ = subprocess_runner( + ("echo", "hello"), cwd=tmp_path, echo_stdout=False + ) + + assert exit_code == 0 + records = _invocation_records(caplog) + assert len(records) == 1 + assert records[0].levelno == logging.INFO + assert f"(cwd={tmp_path})" in records[0].getMessage() From 95a34965c081fcfd04990f94ea36c11a88651911 Mon Sep 17 00:00:00 2001 From: leynos Date: Wed, 10 Jun 2026 02:18:38 +0200 Subject: [PATCH 2/8] Harden subprocess logging regression test assertions Address review feedback on the single-invocation-log regression test: - Loosen the INFO message assertion so it checks the stable prefix ("Running external command") and the command ("echo hello") rather than the full formatted string, keeping the test robust to wording or spacing changes. - Restrict `_invocation_records` to the INFO command line only, and add an explicit `_assert_no_spawn_record` check that the removed DEBUG "Spawning subprocess:" log is absent, tying the regression directly to #104. Co-Authored-By: Claude Opus 4.8 (1M context) --- tests/unit/test_subprocess_runner_logging.py | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/tests/unit/test_subprocess_runner_logging.py b/tests/unit/test_subprocess_runner_logging.py index 5ca448ea..faf37cc4 100644 --- a/tests/unit/test_subprocess_runner_logging.py +++ b/tests/unit/test_subprocess_runner_logging.py @@ -33,10 +33,16 @@ def _invocation_records( record for record in caplog.records if "Running external command" in record.getMessage() - or "Spawning subprocess:" in record.getMessage() ] +def _assert_no_spawn_record(caplog: LogCaptureFixture) -> None: + """Assert the removed DEBUG spawn log is absent (regression for #104).""" + assert all( + "Spawning subprocess:" not in record.getMessage() for record in caplog.records + ) + + def test_command_logged_exactly_once(caplog: LogCaptureFixture) -> None: """A command produces a single invocation log record at INFO.""" caplog.set_level(logging.DEBUG, logger=_RUNNER_LOGGER) @@ -49,7 +55,10 @@ def test_command_logged_exactly_once(caplog: LogCaptureFixture) -> None: records = _invocation_records(caplog) assert len(records) == 1 assert records[0].levelno == logging.INFO - assert "Running external command: echo hello" in records[0].getMessage() + message = records[0].getMessage() + assert "Running external command" in message + assert "echo hello" in message + _assert_no_spawn_record(caplog) def test_command_logged_exactly_once_with_cwd( @@ -67,3 +76,4 @@ def test_command_logged_exactly_once_with_cwd( assert len(records) == 1 assert records[0].levelno == logging.INFO assert f"(cwd={tmp_path})" in records[0].getMessage() + _assert_no_spawn_record(caplog) From f5ab030fee14d500a2d5d7198272ee47dfd44e30 Mon Sep 17 00:00:00 2001 From: leynos Date: Wed, 10 Jun 2026 02:28:27 +0200 Subject: [PATCH 3/8] Log cmd-mox passthrough command invocations The cmd-mox passthrough path in `_handle_cmd_mox_passthrough` calls `invoke_via_subprocess` directly rather than going through `subprocess_runner`, so it never reached the `log_command_invocation` call. Once the redundant DEBUG spawn log was removed for #104, these passthrough external commands emitted no command/cwd invocation record at all, regressing command observability. Emit the single INFO invocation record at the passthrough call site via `log_command_invocation`, mirroring `subprocess_runner`. Routing through `subprocess_runner` is not viable here because that wrapper does not accept `stdin_data`, which the passthrough path needs. Extend the passthrough streaming test to assert exactly one INFO invocation record is logged for the passthrough command. Co-Authored-By: Claude Opus 4.8 (1M context) --- lading/testing/cmd_mox_runner.py | 8 ++++++++ tests/unit/publish/test_command_logging.py | 16 ++++++++++++++++ 2 files changed, 24 insertions(+) diff --git a/lading/testing/cmd_mox_runner.py b/lading/testing/cmd_mox_runner.py index 4c0cb02a..f0f22686 100644 --- a/lading/testing/cmd_mox_runner.py +++ b/lading/testing/cmd_mox_runner.py @@ -3,6 +3,7 @@ from __future__ import annotations import collections.abc as cabc +import logging import os import sys import typing as typ @@ -17,7 +18,9 @@ split_command, write_to_sink, ) +from lading.utils.process import log_command_invocation +_LOGGER = logging.getLogger(__name__) _CMD_MOX_TIMEOUT_DEFAULT = 5.0 @@ -219,6 +222,11 @@ def _handle_cmd_mox_passthrough( env=passthrough_env, stdin_data=invocation.stdin or None, ) + passthrough_command = (str(resolved), *invocation.args) + # This passthrough path calls ``invoke_via_subprocess`` directly rather than + # going through ``subprocess_runner``, so the single INFO invocation record + # must be emitted here; otherwise these external commands log nothing. + log_command_invocation(_LOGGER, passthrough_command, cwd) exit_code, stdout, stderr = invoke_via_subprocess( str(resolved), tuple(invocation.args), diff --git a/tests/unit/publish/test_command_logging.py b/tests/unit/publish/test_command_logging.py index 33d922e2..854d3a8c 100644 --- a/tests/unit/publish/test_command_logging.py +++ b/tests/unit/publish/test_command_logging.py @@ -83,10 +83,12 @@ def test_invoke_proxies_command_output( def test_cmd_mox_passthrough_streams_output( cmd_mox: CmdMox, capsys: CaptureFixture[str], + caplog: LogCaptureFixture, monkeypatch: MonkeyPatch, use_real_invoke: None, ) -> None: """cmd-mox passthrough should stream via the subprocess runner.""" + caplog.set_level(logging.INFO, logger="lading.testing.cmd_mox_runner") monkeypatch.setenv("LADING_USE_CMD_MOX_STUB", "1") script = "print('unused')" cmd_mox.spy(sys.executable).with_args("-c", script).passthrough() @@ -132,3 +134,17 @@ def fake_echo(payload: str, sink: typ.TextIO) -> None: assert captured.err == "beta" assert calls == [(sys.executable, ("-c", script), None)] assert not echo_payloads + # The passthrough path bypasses ``subprocess_runner``, so it must emit the + # single INFO invocation record itself (regression for #104). + invocation_records = [ + record + for record in caplog.records + if "Running external command" in record.getMessage() + ] + assert len(invocation_records) == 1 + assert invocation_records[0].levelno == logging.INFO + message = invocation_records[0].getMessage() + assert "-c" in message + # ``script`` is shell-quoted in the rendered command line, so match on its + # inner content rather than the raw string. + assert "unused" in message From 3da1df23a247bf6a8ec26ccffb563d33eae029e9 Mon Sep 17 00:00:00 2001 From: leynos Date: Wed, 10 Jun 2026 12:52:54 +0200 Subject: [PATCH 4/8] Reduce passthrough test fixture argument count `test_cmd_mox_passthrough_streams_output` took five parameters, four of which were pytest infrastructure fixtures. Collapse `capsys`, `caplog`, `monkeypatch`, and `use_real_invoke` into a single `request` parameter and resolve them via `request.getfixturevalue` at the top of the body, keeping `cmd_mox` as the only explicit fixture. The `pytest.FixtureRequest` annotation stays lazy thanks to `from __future__ import annotations`, so it does not trigger a runtime lookup of the `TYPE_CHECKING`-only `pytest` import. Co-Authored-By: Claude Opus 4.8 (1M context) --- tests/unit/publish/test_command_logging.py | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/tests/unit/publish/test_command_logging.py b/tests/unit/publish/test_command_logging.py index 854d3a8c..87712b89 100644 --- a/tests/unit/publish/test_command_logging.py +++ b/tests/unit/publish/test_command_logging.py @@ -82,12 +82,13 @@ def test_invoke_proxies_command_output( def test_cmd_mox_passthrough_streams_output( cmd_mox: CmdMox, - capsys: CaptureFixture[str], - caplog: LogCaptureFixture, - monkeypatch: MonkeyPatch, - use_real_invoke: None, + request: pytest.FixtureRequest, ) -> None: """cmd-mox passthrough should stream via the subprocess runner.""" + capsys: CaptureFixture[str] = request.getfixturevalue("capsys") + caplog: LogCaptureFixture = request.getfixturevalue("caplog") + monkeypatch: MonkeyPatch = request.getfixturevalue("monkeypatch") + request.getfixturevalue("use_real_invoke") caplog.set_level(logging.INFO, logger="lading.testing.cmd_mox_runner") monkeypatch.setenv("LADING_USE_CMD_MOX_STUB", "1") script = "print('unused')" From 51f17f7cd33e83930f4cf14d15299dfc135710f2 Mon Sep 17 00:00:00 2001 From: leynos Date: Wed, 10 Jun 2026 12:55:52 +0200 Subject: [PATCH 5/8] Add descriptive failure messages to logging regression asserts Annotate every assertion in the subprocess runner logging regression tests with a trailing message so failures explain the expected context: exit code, stdout/stderr contents, invocation record count, log level, message substrings, cwd inclusion, and the absence of the removed "Spawning subprocess:" DEBUG record. The spawn-absence message lives in `_assert_no_spawn_record` itself, since that helper raises the failure. Co-Authored-By: Claude Opus 4.8 (1M context) --- tests/unit/test_subprocess_runner_logging.py | 28 +++++++++++--------- 1 file changed, 16 insertions(+), 12 deletions(-) diff --git a/tests/unit/test_subprocess_runner_logging.py b/tests/unit/test_subprocess_runner_logging.py index faf37cc4..36cefdca 100644 --- a/tests/unit/test_subprocess_runner_logging.py +++ b/tests/unit/test_subprocess_runner_logging.py @@ -40,7 +40,7 @@ def _assert_no_spawn_record(caplog: LogCaptureFixture) -> None: """Assert the removed DEBUG spawn log is absent (regression for #104).""" assert all( "Spawning subprocess:" not in record.getMessage() for record in caplog.records - ) + ), "Unexpected 'Spawning subprocess:' log emitted" def test_command_logged_exactly_once(caplog: LogCaptureFixture) -> None: @@ -49,15 +49,17 @@ def test_command_logged_exactly_once(caplog: LogCaptureFixture) -> None: exit_code, stdout, stderr = subprocess_runner(("echo", "hello"), echo_stdout=False) - assert exit_code == 0 - assert stdout.strip() == "hello" - assert stderr == "" + assert exit_code == 0, "expected exit code 0" + assert stdout.strip() == "hello", 'expected stdout to contain "hello"' + assert stderr == "", "expected empty stderr" records = _invocation_records(caplog) - assert len(records) == 1 - assert records[0].levelno == logging.INFO + assert len(records) == 1, "expected exactly one invocation record" + assert records[0].levelno == logging.INFO, "expected invocation at INFO level" message = records[0].getMessage() - assert "Running external command" in message - assert "echo hello" in message + assert "Running external command" in message, ( + "expected message to contain 'Running external command'" + ) + assert "echo hello" in message, "expected message to contain 'echo hello'" _assert_no_spawn_record(caplog) @@ -71,9 +73,11 @@ def test_command_logged_exactly_once_with_cwd( ("echo", "hello"), cwd=tmp_path, echo_stdout=False ) - assert exit_code == 0 + assert exit_code == 0, "expected exit code 0" records = _invocation_records(caplog) - assert len(records) == 1 - assert records[0].levelno == logging.INFO - assert f"(cwd={tmp_path})" in records[0].getMessage() + assert len(records) == 1, "expected exactly one invocation record" + assert records[0].levelno == logging.INFO, "expected invocation at INFO level" + assert f"(cwd={tmp_path})" in records[0].getMessage(), ( + "expected cwd to appear in invocation message" + ) _assert_no_spawn_record(caplog) From f455987673eaaf226aa615cfacf41e66a3ad8b07 Mon Sep 17 00:00:00 2001 From: leynos Date: Wed, 10 Jun 2026 13:12:00 +0200 Subject: [PATCH 6/8] Document single-invocation logging contract (#104) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Record the subprocess invocation logging contract introduced by #111 in developer-facing docs: - developers-guide: add a "Subprocess invocation logging" sub-section to the command runners section, describing the single INFO record (with optional cwd suffix) and the separate DEBUG environment-overrides record, and pointing at the pinning regression tests. - roadmap: mark "Stop double-logging external command invocations" as complete under Phase 4 → Step 4.1 with outcome and completion criteria. Co-Authored-By: Claude Opus 4.8 (1M context) --- docs/developers-guide.md | 16 ++++++++++++++++ docs/roadmap.md | 8 ++++++++ 2 files changed, 24 insertions(+) diff --git a/docs/developers-guide.md b/docs/developers-guide.md index 2804c67b..9e62a54a 100644 --- a/docs/developers-guide.md +++ b/docs/developers-guide.md @@ -535,6 +535,22 @@ around command execution. `lading bump` uses the runtime runner directly for lockfile refreshes, while `lading publish` uses `_invoke` where failures should surface as `PublishPreflightError`. +#### Subprocess invocation logging + +`subprocess_runner` emits **exactly one** log record per external command +invocation: + +- **INFO** — `Running external command: []` (with an optional + `(cwd=)` suffix when a working directory is supplied). This is the + operationally visible record. +- **DEBUG** (separate, only when environment overrides are present) — a + redacted summary of the environment variables that differ from the ambient + process environment. + +No second invocation record is emitted at DEBUG level. Any regression that +reintroduces a second invocation log at any level is pinned by the tests in +`tests/unit/test_subprocess_runner_logging.py`. + ### Pre-flight validation (`publish_preflight`) `lading.commands.publish_preflight` performs workspace validation before any diff --git a/docs/roadmap.md b/docs/roadmap.md index 0d326f42..916d31cb 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -257,6 +257,14 @@ behaviours. one for `publish --dry-run` that validates the full sequence of operations on a non-trivial fixture workspace. +- [x] **Stop double-logging external command invocations (`#104`):** + + - **Outcome:** `subprocess_runner` emits exactly one INFO-level invocation + log per external command; the redundant DEBUG spawn log is removed. + - **Completion Criteria:** Regression tests in + `tests/unit/test_subprocess_runner_logging.py` assert a single INFO record + and the absence of any "Spawning subprocess:" record. + ______________________________________________________________________ ### **Step 4.2: User Documentation and Release** From e483c4116c2c3feec03cfa0fe072592f343a7b3f Mon Sep 17 00:00:00 2001 From: leynos Date: Wed, 10 Jun 2026 13:15:35 +0200 Subject: [PATCH 7/8] Snapshot subprocess invocation log messages Replace the substring assertions on the invocation log message with syrupy snapshot assertions in the subprocess runner logging regression tests. The cwd test redacts the temporary directory to the literal ```` token before comparing so the snapshot stays stable across runs. Add the corresponding amber snapshot file. Co-Authored-By: Claude Opus 4.8 (1M context) --- .../test_subprocess_runner_logging.ambr | 7 ++++++ tests/unit/test_subprocess_runner_logging.py | 22 ++++++++++--------- 2 files changed, 19 insertions(+), 10 deletions(-) create mode 100644 tests/unit/__snapshots__/test_subprocess_runner_logging.ambr diff --git a/tests/unit/__snapshots__/test_subprocess_runner_logging.ambr b/tests/unit/__snapshots__/test_subprocess_runner_logging.ambr new file mode 100644 index 00000000..8bc14bd9 --- /dev/null +++ b/tests/unit/__snapshots__/test_subprocess_runner_logging.ambr @@ -0,0 +1,7 @@ +# serializer version: 1 +# name: test_command_logged_exactly_once + 'Running external command: echo hello' +# --- +# name: test_command_logged_exactly_once_with_cwd + 'Running external command: echo hello (cwd=)' +# --- diff --git a/tests/unit/test_subprocess_runner_logging.py b/tests/unit/test_subprocess_runner_logging.py index 36cefdca..42e0074b 100644 --- a/tests/unit/test_subprocess_runner_logging.py +++ b/tests/unit/test_subprocess_runner_logging.py @@ -16,11 +16,13 @@ from pathlib import Path import pytest + from syrupy.assertion import SnapshotAssertion LogCaptureFixture = pytest.LogCaptureFixture else: # pragma: no cover - typing helpers Path = typ.Any LogCaptureFixture = typ.Any + SnapshotAssertion = typ.Any _RUNNER_LOGGER = "lading.runtime.subprocess_runner" @@ -43,7 +45,10 @@ def _assert_no_spawn_record(caplog: LogCaptureFixture) -> None: ), "Unexpected 'Spawning subprocess:' log emitted" -def test_command_logged_exactly_once(caplog: LogCaptureFixture) -> None: +def test_command_logged_exactly_once( + caplog: LogCaptureFixture, + snapshot: SnapshotAssertion, +) -> None: """A command produces a single invocation log record at INFO.""" caplog.set_level(logging.DEBUG, logger=_RUNNER_LOGGER) @@ -55,16 +60,14 @@ def test_command_logged_exactly_once(caplog: LogCaptureFixture) -> None: records = _invocation_records(caplog) assert len(records) == 1, "expected exactly one invocation record" assert records[0].levelno == logging.INFO, "expected invocation at INFO level" - message = records[0].getMessage() - assert "Running external command" in message, ( - "expected message to contain 'Running external command'" - ) - assert "echo hello" in message, "expected message to contain 'echo hello'" + assert records[0].getMessage() == snapshot(), "expected message to match snapshot" _assert_no_spawn_record(caplog) def test_command_logged_exactly_once_with_cwd( - caplog: LogCaptureFixture, tmp_path: Path + caplog: LogCaptureFixture, + tmp_path: Path, + snapshot: SnapshotAssertion, ) -> None: """The single invocation record includes the working directory.""" caplog.set_level(logging.DEBUG, logger=_RUNNER_LOGGER) @@ -77,7 +80,6 @@ def test_command_logged_exactly_once_with_cwd( records = _invocation_records(caplog) assert len(records) == 1, "expected exactly one invocation record" assert records[0].levelno == logging.INFO, "expected invocation at INFO level" - assert f"(cwd={tmp_path})" in records[0].getMessage(), ( - "expected cwd to appear in invocation message" - ) + redacted = records[0].getMessage().replace(str(tmp_path), "") + assert redacted == snapshot(), "expected redacted cwd message to match snapshot" _assert_no_spawn_record(caplog) From ce7944908fdbfe2aecd5d9af7ac71e783655ddc9 Mon Sep 17 00:00:00 2001 From: leynos Date: Wed, 10 Jun 2026 13:33:47 +0200 Subject: [PATCH 8/8] Log subprocess environment only when overrides exist `_log_subprocess_environment` emitted a DEBUG "Spawning subprocess with inherited environment" record on every invocation without overrides, adding noise that carried no information beyond the INFO invocation line. Return early when no overrides are present so a DEBUG record is only emitted when there are actual environment overrides to report. Co-Authored-By: Claude Opus 4.8 (1M context) --- lading/runtime/subprocess_runner.py | 1 - 1 file changed, 1 deletion(-) diff --git a/lading/runtime/subprocess_runner.py b/lading/runtime/subprocess_runner.py index 72f24ece..fd04886b 100644 --- a/lading/runtime/subprocess_runner.py +++ b/lading/runtime/subprocess_runner.py @@ -348,7 +348,6 @@ def _format_thread_name(program: str, stream: str) -> str: def _log_subprocess_environment(env: cabc.Mapping[str, str] | None) -> None: """Log redacted environment overrides for subprocess execution.""" if not env: - _LOGGER.debug("Spawning subprocess with inherited environment") return redacted = _redact_environment(env) _LOGGER.debug("Subprocess environment overrides: %s", redacted)