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/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..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( @@ -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 diff --git a/tests/unit/test_subprocess_runner_logging.py b/tests/unit/test_subprocess_runner_logging.py new file mode 100644 index 00000000..faf37cc4 --- /dev/null +++ b/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)