📝 CodeRabbit Chat: Implement requested code changes

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:

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/publish/test_command_logging.py

@@ -20,13 +20,15 @@
     LogCaptureFixture = pytest.LogCaptureFixture
     CaptureFixture = pytest.CaptureFixture
     MonkeyPatch = pytest.MonkeyPatch
+    FixtureRequest = pytest.FixtureRequest
 else:  # pragma: no cover - typing helpers
     Path = typ.Any
     LogCaptureFixture = typ.Any
     CaptureFixture = typ.Any
     CmdMox = typ.Any
     MonkeyPatch = typ.Any
     SubprocessContext = typ.Any
+    FixtureRequest = typ.Any
 
 
 def test_invoke_logs_command_with_cwd(
@@ -84,12 +86,15 @@ def test_cmd_mox_passthrough_streams_output(
     cmd_mox: CmdMox,
     capsys: CaptureFixture[str],
     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]] = []
 
@@ -132,3 +137,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,79 @@
+"""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()
+    ]
+
+
+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)
+
+    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
+    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(
+    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()
+    _assert_no_spawn_record(caplog)