From b0dca3f77d09ef20cc206f70d2220214d89352c9 Mon Sep 17 00:00:00 2001 From: leynos Date: Tue, 9 Jun 2026 21:46:39 +0200 Subject: [PATCH 1/4] 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/4] 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/4] 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 fb8a583f59bd08e5c19d6fce5f3b4c262140eca4 Mon Sep 17 00:00:00 2001 From: "coderabbitai[bot]" <136622811+coderabbitai[bot]@users.noreply.github.com> Date: Wed, 10 Jun 2026 10:21:22 +0000 Subject: [PATCH 4/4] =?UTF-8?q?=F0=9F=93=9D=20CodeRabbit=20Chat:=20Impleme?= =?UTF-8?q?nt=20requested=20code=20changes?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- tests/unit/publish/test_command_logging.py | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/tests/unit/publish/test_command_logging.py b/tests/unit/publish/test_command_logging.py index 854d3a8c..326c16f4 100644 --- a/tests/unit/publish/test_command_logging.py +++ b/tests/unit/publish/test_command_logging.py @@ -20,6 +20,7 @@ LogCaptureFixture = pytest.LogCaptureFixture CaptureFixture = pytest.CaptureFixture MonkeyPatch = pytest.MonkeyPatch + FixtureRequest = pytest.FixtureRequest else: # pragma: no cover - typing helpers Path = typ.Any LogCaptureFixture = typ.Any @@ -27,6 +28,7 @@ CmdMox = typ.Any MonkeyPatch = typ.Any SubprocessContext = typ.Any + FixtureRequest = typ.Any def test_invoke_logs_command_with_cwd( @@ -83,15 +85,16 @@ 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: FixtureRequest, ) -> None: """cmd-mox passthrough should stream via the subprocess runner.""" + caplog: LogCaptureFixture = request.getfixturevalue("caplog") + 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')" - cmd_mox.spy(sys.executable).with_args("-c", script).passthrough() + calls: list[tuple[str, tuple[str, ...], str | None]] = []