fix: prefix external command output for better log clarity

Most log output uses the package name as a prefix (via FromagerLogRecord)
so it is possible to tell which package is being processed when a message
is logged. However, external command output (like uv) lacked the package
name on continuation lines, making it difficult to grep for all output
related to a specific package.

This fix adds the package name to every line of external command output
by manually prefixing each line. The package name is retrieved from the
log context using a new helper function and added to each continuation
line, enabling grep to find all lines related to a specific package
(e.g., `grep 'numpy:'`).

Implementation:
- Add get_log_prefix() helper in log.py to extract package name + version
- Refactor FromagerLogRecord.getMessage() to use the helper
- Use shlex.join() for command formatting in external_commands.py
- Single logger call combining command info and output
- str.replace() with f-string to add prefixes to each line
- Hybrid .format() and f-string approach for Python 3.11 compatibility

Benefits:
- Every line has package name prefix for grep
- Parallel builds: Single log call prevents line interleaving
- Simple implementation with no code duplication
- No extra visual markers - clean, consistent output

Example output:
  numpy-1.0.0: command failed with exit code 1: uv pip install numpy
  numpy-1.0.0: Resolving dependencies...
  numpy-1.0.0: Error: Could not find package

Tests:
- Added test_external_command_output_prefix() to verify prefixing
- Uses pytest fixtures to capture and validate log output
- Verifies every line includes the package name for greppability

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,30 @@ def run(
             stdin=stdin,
         )
         output = completed.stdout.decode("utf-8") if completed.stdout else ""
+
+    # Prefix output lines with package name/version for greppability
+    formatted_output = None
+    if output:
+        prefix = log.get_log_prefix()
+        if prefix:
+            # Add prefix to all lines for greppability
+            formatted_output = "{}: {}".format(
+                prefix,
+                output.replace("\n", f"\n{prefix}: "),
+            )
+        else:
+            formatted_output = output
+
     if completed.returncode != 0:
-        logger.error("%s failed with %s", cmd, output)
+        # Log complete error message with command, exit code, and output
+        output_to_log = "\n" + formatted_output if formatted_output else ""
+        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 +137,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 with visual prefix to distinguish from fromager output
+    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,40 @@ 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."""
+    req = Requirement("test-package==1.0.0")
+    version = Version("1.0.0")
+
+    # Set up logging context with requirement and version
+    token_req = log.requirement_ctxvar.set(req)
+    token_ver = log.version_ctxvar.set(version)
+
+    try:
+        with caplog.at_level(logging.DEBUG, logger="fromager.external_commands"):
+            # Run a command that produces multi-line output
+            external_commands.run(["echo", "-e", "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
+        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:
+        # Clean up context variables
+        log.requirement_ctxvar.reset(token_req)
+        log.version_ctxvar.reset(token_ver)