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 <claude@anthropic.com>

Signed-off-by: Ioannis Angelakopoulos <iangelak@redhat.com>

Author: iangelak

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

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

tests/test_external_commands.py

@@ -1,12 +1,15 @@
+import logging
 import os
 import pathlib
 import subprocess
 import typing
 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)