Stop double-logging external command invocations (#104)

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: <cmd> [<args>]` (with an optional
+  `(cwd=<path>)` 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

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**

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)

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),

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=<tmpdir>)'
+# ---

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

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), "<tmpdir>")
+    assert redacted == snapshot(), "expected redacted cwd message to match snapshot"
+    _assert_no_spawn_record(caplog)