Fix debug logging for build with a build script (#8760)

Co-authored-by: Randy Döring <30527984+radoering@users.noreply.github.com>

src/poetry/console/logging/io_formatter.py

@@ -1,7 +1,10 @@
 from __future__ import annotations
 
 import logging
+import sys
+import textwrap
 
+from pathlib import Path
 from typing import TYPE_CHECKING
 
 from poetry.console.logging.filters import POETRY_FILTER
@@ -32,8 +35,37 @@ def format(self, record: LogRecord) -> str:
 
             record.msg = msg
 
+        formatted = super().format(record)
+
         if not POETRY_FILTER.filter(record):
-            # prefix third-party packages with name for easier debugging
-            record.msg = f"[{record.name}] {record.msg}"
+            # prefix all lines from third-party packages for easier debugging
+            formatted = textwrap.indent(
+                formatted, f"[{_log_prefix(record)}] ", lambda line: True
+            )
+
+        return formatted
+
+
+def _log_prefix(record: LogRecord) -> str:
+    prefix = _path_to_package(Path(record.pathname)) or record.module
+    if record.name != "root":
+        prefix = ":".join([prefix, record.name])
+    return prefix
+
 
-        return super().format(record)
+def _path_to_package(path: Path) -> str | None:
+    """Return main package name from the LogRecord.pathname."""
+    prefix: Path | None = None
+    # Find the most specific prefix in sys.path.
+    # We have to search the entire sys.path because a subsequent path might be
+    # a sub path of the first match and thereby a better match.
+    for syspath in sys.path:
+        if (
+            prefix and prefix in (p := Path(syspath)).parents and p in path.parents
+        ) or (not prefix and (p := Path(syspath)) in path.parents):
+            prefix = p
+    if not prefix:
+        # this is unexpected, but let's play it safe
+        return None
+    path = path.relative_to(prefix)
+    return path.parts[0]  # main package name

src/poetry/utils/env/__init__.py

@@ -67,35 +67,27 @@ def build_environment(
     """
     if not env or poetry.package.build_script:
         with ephemeral_environment(executable=env.python if env else None) as venv:
-            overwrite = (
-                io is not None and io.output.is_decorated() and not io.is_debug()
-            )
-
             if io:
-                if not overwrite:
-                    io.write_error_line("")
-
                 requires = [
                     f"<c1>{requirement}</c1>"
                     for requirement in poetry.pyproject.build_system.requires
                 ]
 
-                io.overwrite_error(
+                io.write_error_line(
                     "<b>Preparing</b> build environment with build-system requirements"
                     f" {', '.join(requires)}"
                 )
 
-            venv.run_pip(
+            output = venv.run_pip(
                 "install",
                 "--disable-pip-version-check",
                 "--ignore-installed",
                 "--no-input",
                 *poetry.pyproject.build_system.requires,
             )
 
-            if overwrite:
-                assert io is not None
-                io.write_error_line("")
+            if io and io.is_debug() and output:
+                io.write_error(output)
 
             yield venv
     else:

src/poetry/utils/env/env_manager.py

@@ -675,7 +675,7 @@ def build_venv(
 
         args.append(str(path))
 
-        cli_result = virtualenv.cli_run(args)
+        cli_result = virtualenv.cli_run(args, setup_logging=False)
 
         # Exclude the venv folder from from macOS Time Machine backups
         # TODO: Add backup-ignore markers for other platforms too

tests/console/logging/test_io_formatter.py

@@ -0,0 +1,85 @@
+from __future__ import annotations
+
+from logging import LogRecord
+from pathlib import Path
+from typing import TYPE_CHECKING
+
+import pytest
+
+from poetry.console.logging.io_formatter import IOFormatter
+from poetry.console.logging.io_formatter import _log_prefix
+from poetry.console.logging.io_formatter import _path_to_package
+
+
+if TYPE_CHECKING:
+    from pytest_mock import MockerFixture
+
+
+@pytest.mark.parametrize(
+    ("record_name", "record_pathname", "record_msg", "expected"),
+    [
+        ("poetry", "foo/bar.py", "msg", "msg"),
+        ("poetry.core", "foo/bar.py", "msg", "msg"),
+        ("baz", "syspath/foo/bar.py", "msg", "[foo:baz] msg"),
+        ("root", "syspath/foo/bar.py", "1\n\n2", "[foo] 1\n[foo] \n[foo] 2"),
+    ],
+)
+def test_format(
+    mocker: MockerFixture,
+    record_name: str,
+    record_pathname: str,
+    record_msg: str,
+    expected: str,
+) -> None:
+    mocker.patch("sys.path", [str(Path("syspath"))])
+    record = LogRecord(record_name, 0, record_pathname, 0, record_msg, (), None)
+    formatter = IOFormatter()
+    assert formatter.format(record) == expected
+
+
+@pytest.mark.parametrize(
+    ("record_name", "record_pathname", "expected"),
+    [
+        ("root", "syspath/foo/bar.py", "foo"),
+        ("baz", "syspath/foo/bar.py", "foo:baz"),
+        ("baz", "unexpected/foo/bar.py", "bar:baz"),
+    ],
+)
+def test_log_prefix(
+    mocker: MockerFixture,
+    record_name: str,
+    record_pathname: str,
+    expected: str,
+) -> None:
+    mocker.patch("sys.path", [str(Path("syspath"))])
+    record = LogRecord(record_name, 0, record_pathname, 0, "msg", (), None)
+    assert _log_prefix(record) == expected
+
+
+@pytest.mark.parametrize(
+    ("path", "expected"),
+    [
+        ("python-l/lib/python3.9/site-packages/foo/bar/baz.py", "foo"),  # Linux
+        ("python-w/lib/site-packages/foo/bar/baz.py", "foo"),  # Windows
+        ("unexpected/foo/bar/baz.py", None),  # unexpected
+    ],
+)
+def test_path_to_package(
+    mocker: MockerFixture, path: str, expected: str | None
+) -> None:
+    mocker.patch(
+        "sys.path",
+        # We just put the Linux and the Windows variants in the path,
+        # so we do not have to create different mocks based on the subtest.
+        [
+            # On Linux, only the site-packages directory is in the path.
+            str(Path("python-l/lib/python3.9/site-packages")),
+            # On Windows, both the base directory and the site-packages directory
+            # are in the path.
+            str(Path("python-w")),
+            str(Path("python-w/other")),  # this one is just to test for robustness
+            str(Path("python-w/lib/site-packages")),
+            str(Path("python-w/lib")),  # this one is just to test for robustness
+        ],
+    )
+    assert _path_to_package(Path(path)) == expected

tests/utils/env/test_env_manager.py

@@ -1,5 +1,6 @@
 from __future__ import annotations
 
+import logging
 import os
 import sys
 
@@ -27,6 +28,7 @@
     from collections.abc import Callable
     from collections.abc import Iterator
 
+    from _pytest.logging import LogCaptureFixture
     from pytest_mock import MockerFixture
 
     from poetry.poetry import Poetry
@@ -1231,6 +1233,16 @@ def mock_check_output(cmd: str, *args: Any, **kwargs: Any) -> str:
     )
 
 
+def test_build_venv_does_not_change_loglevel(
+    tmp_path: Path, manager: EnvManager, caplog: LogCaptureFixture
+) -> None:
+    # see https://github.com/python-poetry/poetry/pull/8760
+    venv_path = tmp_path / "venv"
+    caplog.set_level(logging.DEBUG)
+    manager.build_venv(venv_path)
+    assert logging.root.level == logging.DEBUG
+
+
 @pytest.mark.skipif(sys.platform != "darwin", reason="requires darwin")
 def test_venv_backup_exclusion(tmp_path: Path, manager: EnvManager) -> None:
     import xattr