Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
35 changes: 33 additions & 2 deletions src/fromager/external_commands.py
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,8 @@
import typing
from io import TextIOWrapper

from . import log

logger = logging.getLogger(__name__)

HERE = pathlib.Path(__file__).absolute().parent
Expand Down Expand Up @@ -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

Comment thread
LalatenduMohanty marked this conversation as resolved.
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
Expand All @@ -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
36 changes: 25 additions & 11 deletions src/fromager/log.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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):
Expand Down
50 changes: 48 additions & 2 deletions tests/test_external_commands.py
Original file line number Diff line number Diff line change
@@ -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:
Expand All @@ -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"],
Expand Down Expand Up @@ -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)
Loading