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** diff --git a/lading/runtime/subprocess_runner.py b/lading/runtime/subprocess_runner.py index 06a655c9..fd04886b 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,21 +345,9 @@ 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: - _LOGGER.debug("Spawning subprocess with inherited environment") return redacted = _redact_environment(env) _LOGGER.debug("Subprocess environment overrides: %s", redacted) 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/__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/publish/test_command_logging.py b/tests/unit/publish/test_command_logging.py index 33d922e2..87712b89 100644 --- a/tests/unit/publish/test_command_logging.py +++ b/tests/unit/publish/test_command_logging.py @@ -82,11 +82,14 @@ def test_invoke_proxies_command_output( def test_cmd_mox_passthrough_streams_output( cmd_mox: CmdMox, - capsys: CaptureFixture[str], - 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')" cmd_mox.spy(sys.executable).with_args("-c", script).passthrough() @@ -132,3 +135,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 diff --git a/tests/unit/test_subprocess_runner_logging.py b/tests/unit/test_subprocess_runner_logging.py new file mode 100644 index 00000000..42e0074b --- /dev/null +++ b/tests/unit/test_subprocess_runner_logging.py @@ -0,0 +1,85 @@ +"""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 + 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" + + +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() + ] + + +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, + snapshot: SnapshotAssertion, +) -> 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, "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, "expected exactly one invocation record" + assert records[0].levelno == logging.INFO, "expected invocation at INFO level" + 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, + snapshot: SnapshotAssertion, +) -> 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, "expected exit code 0" + records = _invocation_records(caplog) + assert len(records) == 1, "expected exactly one invocation record" + assert records[0].levelno == logging.INFO, "expected invocation at INFO level" + redacted = records[0].getMessage().replace(str(tmp_path), "") + assert redacted == snapshot(), "expected redacted cwd message to match snapshot" + _assert_no_spawn_record(caplog)