From 792432ce1343eb9ff8480d6f5db3676a5622d977 Mon Sep 17 00:00:00 2001 From: Ioannis Angelakopoulos Date: Tue, 11 Nov 2025 15:09:43 -0500 Subject: [PATCH] fix: prefix external command output for better log clarity External command output lacked package prefixes on continuation lines, making logs hard to grep in parallel builds. Solution: Added get_log_prefix() helper to extract package context. FromagerLogRecord prefixes the first line, str.replace() handles continuation lines. Fixes: #753 Co-authored-by: Claude Signed-off-by: Ioannis Angelakopoulos --- src/fromager/external_commands.py | 35 ++++++++++++++++++++-- src/fromager/log.py | 36 +++++++++++++++------- tests/test_external_commands.py | 50 +++++++++++++++++++++++++++++-- 3 files changed, 106 insertions(+), 15 deletions(-) diff --git a/src/fromager/external_commands.py b/src/fromager/external_commands.py index f23b20aa..e190bcb5 100644 --- a/src/fromager/external_commands.py +++ b/src/fromager/external_commands.py @@ -7,6 +7,8 @@ import typing from io import TextIOWrapper +from . import log + logger = logging.getLogger(__name__) HERE = pathlib.Path(__file__).absolute().parent @@ -98,8 +100,33 @@ def run( stdin=stdin, ) output = completed.stdout.decode("utf-8") if completed.stdout else "" + + # Add package prefix to continuation lines for greppability + prefix = log.get_log_prefix() + formatted_output = None + + if output: + if prefix: + # FromagerLogRecord handles first line, we handle continuation lines + formatted_output = output.rstrip("\n").replace("\n", f"\n{prefix}: ") + else: + formatted_output = output + if completed.returncode != 0: - logger.error("%s failed with %s", cmd, output) + # Prefix first line for error output (embedded in larger message) + if formatted_output and prefix: + output_to_log = f"\n{prefix}: {formatted_output}" + elif formatted_output: + output_to_log = f"\n{formatted_output}" + else: + output_to_log = "" + logger.error( + "command failed with exit code %d: %s%s", + completed.returncode, + shlex.join(cmd), + output_to_log, + ) + err_type = subprocess.CalledProcessError if network_isolation: # Look for a few common messages that mean there is a network @@ -113,5 +140,9 @@ def run( if substr in output: err_type = NetworkIsolationError raise err_type(completed.returncode, cmd, output) - logger.debug("output: %s", output) + + # Log command output for debugging + if formatted_output: + logger.debug(formatted_output) + return output diff --git a/src/fromager/log.py b/src/fromager/log.py index 0226fe1a..7598ecfb 100644 --- a/src/fromager/log.py +++ b/src/fromager/log.py @@ -17,6 +17,27 @@ version_ctxvar: contextvars.ContextVar[Version] = contextvars.ContextVar("version") +def get_log_prefix() -> str | None: + """Get the log prefix based on current context (requirement and version). + + Returns: + - "name-version" if both requirement and version are available + - "name" if only requirement is available + - None if no context is available + """ + try: + req = requirement_ctxvar.get() + except LookupError: + return None + else: + try: + version = version_ctxvar.get() + except LookupError: + return req.name + else: + return f"{req.name}-{version}" + + @contextlib.contextmanager def req_ctxvar_context( req: Requirement, version: Version | None = None @@ -53,17 +74,10 @@ class FromagerLogRecord(logging.LogRecord): def getMessage(self) -> str: # noqa: N802 msg = super().getMessage() - try: - req = requirement_ctxvar.get() - except LookupError: - return msg - else: - try: - version = version_ctxvar.get() - except LookupError: - return f"{req.name}: {msg}" - else: - return f"{req.name}-{version}: {msg}" + prefix = get_log_prefix() + if prefix: + return f"{prefix}: {msg}" + return msg class ThreadLogFilter(logging.Filter): diff --git a/tests/test_external_commands.py b/tests/test_external_commands.py index 87d2bae0..94961a81 100644 --- a/tests/test_external_commands.py +++ b/tests/test_external_commands.py @@ -1,3 +1,4 @@ +import logging import os import pathlib import subprocess @@ -5,8 +6,10 @@ from unittest import mock import pytest +from packaging.requirements import Requirement +from packaging.version import Version -from fromager import external_commands +from fromager import external_commands, log def test_external_commands_environ() -> None: @@ -29,7 +32,10 @@ def test_external_commands_log_file(tmp_path: pathlib.Path) -> None: assert "test\n" == file_contents -@mock.patch("subprocess.run", return_value=mock.Mock(returncode=0)) +@mock.patch( + "subprocess.run", + return_value=mock.Mock(returncode=0, stdout=b"test output\n"), +) @mock.patch( "fromager.external_commands.network_isolation_cmd", return_value=["/bin/unshare", "--net", "--map-current-user"], @@ -85,3 +91,43 @@ def test_external_commands_network_isolation_real() -> None: ) exc = typing.cast(subprocess.CalledProcessError, e.value) assert exc.returncode == 1 + + +def test_external_command_output_prefix(caplog: pytest.LogCaptureFixture) -> None: + """Test that external command output is prefixed with package name on each line.""" + # Set up the log record factory to enable automatic prefixing + old_factory = logging.getLogRecordFactory() + logging.setLogRecordFactory(log.FromagerLogRecord) + + try: + req = Requirement("test-package==1.0.0") + version = Version("1.0.0") + + with log.req_ctxvar_context(req, version): + with caplog.at_level(logging.DEBUG, logger="fromager.external_commands"): + # Run a command that produces multi-line output + # Use printf for cross-platform compatibility (echo -e doesn't work on macOS) + external_commands.run(["printf", "line1\\nline2\\nline3"]) + + # Get the last debug log record (the output message) + output_rec = caplog.records[-1] + message = output_rec.getMessage() + + # Verify that each line has the package name prefix + # The first line gets the prefix from FromagerLogRecord.getMessage() + # Continuation lines get it from external_commands.run() + expected_prefix = "test-package-1.0.0: " + assert message.startswith(expected_prefix), ( + f"Message should start with '{expected_prefix}'" + ) + + # Check that all lines have the prefix + lines = message.split("\n") + for line in lines: + if line: # Skip empty lines + assert line.startswith(expected_prefix), ( + f"Line '{line}' should start with '{expected_prefix}'" + ) + finally: + # Restore the original log record factory + logging.setLogRecordFactory(old_factory)