Add detail to traced values where str() is ambiguous

changelog/729.feature.rst

@@ -0,0 +1,5 @@
+Traced values now gain detail where ``str()`` is ambiguous: an empty string or a string
+carrying whitespace is quoted, an enum member shows its name, and a path shows its type,
+so that two arguments pointing at the same place are distinguishable. Values that read
+unambiguously as themselves are unchanged, and a value spanning several lines is drawn
+as a block attached to its key instead of running into the surrounding trace.

docs/index.rst

@@ -1030,6 +1030,25 @@ undo function to disable the behaviour.
     pm.trace.root.setwriter(print)
     undo = pm.enable_tracing()
 
+Each hook call is traced with its keyword arguments, followed by a ``finish``
+line carrying the result::
+
+    he_method1 [hook]
+        plugin_name: example
+        path: PosixPath('/tmp')
+        reason: 'needs a network connection'
+        status: <ExitCode.TESTS_FAILED: 1>
+        explanation:
+          | first line
+          \ second line
+    finish he_method1 --> ['value'] [hook]
+
+Values are rendered with :func:`str` wherever that reads unambiguously, and with
+:func:`repr` where it does not: an empty string, a string carrying whitespace,
+an enum member, or a path, whose type is otherwise easy to lose. A value
+spanning several lines is drawn as a block so that it stays attached to its key
+instead of running into the surrounding trace.
+
 
 Call monitoring
 ---------------

src/pluggy/_tracing.py

@@ -6,20 +6,22 @@
 
 from collections.abc import Callable
 from collections.abc import Sequence
+import enum
+import os
 from typing import Any
 
 
 _Writer = Callable[[str], object]
 _Processor = Callable[[tuple[str, ...], tuple[Any, ...]], object]
 
 
-def _describe_str_failure(exc: Exception, obj: object) -> str:
+def _describe_failure(exc: Exception, obj: object, func: str) -> str:
     try:
         exc_info = repr(exc)
     except Exception:
         exc_info = f"unpresentable {type(exc).__name__}"
     name = type(obj).__name__
-    return f"<[{exc_info} raised in str()] {name} object at 0x{id(obj):x}>"
+    return f"<[{exc_info} raised in {func}()] {name} object at 0x{id(obj):x}>"
 
 
 def _escape_surrogates(text: str) -> str:
@@ -42,7 +44,55 @@ def _safe_str(obj: object) -> str:
     try:
         text = str(obj)
     except Exception as exc:
-        text = _describe_str_failure(exc, obj)
+        text = _describe_failure(exc, obj, "str")
+    return _escape_surrogates(text)
+
+
+def _is_plain_token(text: str) -> bool:
+    """Whether ``text`` can be shown bare, without quotes around it."""
+    return bool(text) and text.isprintable() and " " not in text
+
+
+def _format_block(indent: str, text: str) -> list[str]:
+    """Draw a multi line value as a box, so it reads as one value.
+
+    The left edge marks every line as continuation, and the final ``\\``
+    closes it, which keeps a block distinguishable from the trace lines
+    around it.
+    """
+    body = text.split("\n")
+    edges = ["|"] * (len(body) - 1) + ["\\"]
+    return [f"{indent}      {edge} {line}\n" for edge, line in zip(edges, body)]
+
+
+def _render_value(obj: object) -> str:
+    """Render a traced value, adding detail only where ``str`` is ambiguous.
+
+    Most values keep their plain ``str`` rendering, which is what makes a trace
+    readable. ``repr`` is used only where ``str`` hides something the reader
+    needs: the type of a path, the name of an enum member, or the boundaries of
+    a string that is empty or carries whitespace.
+    """
+    if isinstance(obj, str):
+        if "\n" in obj or "\r" in obj:
+            return _safe_str(obj)
+        if _is_plain_token(obj):
+            return _safe_str(obj)
+        return _safe_repr(obj)
+    if isinstance(obj, (enum.Enum, os.PathLike)):
+        return _safe_repr(obj)
+    return _safe_str(obj)
+
+
+def _safe_repr(obj: object) -> str:
+    """``repr(obj)`` for tracing, with a failing ``__repr__`` rendered, not raised.
+
+    The result has lone surrogates escaped, so any text writer accepts it.
+    """
+    try:
+        text = repr(obj)
+    except Exception as exc:
+        text = _describe_failure(exc, obj, "repr")
     return _escape_surrogates(text)
 
 
@@ -68,7 +118,12 @@ def _format_message(self, tags: Sequence[str], args: Sequence[object]) -> str:
         lines = [f"{indent}{content} [{':'.join(tags)}]\n"]
 
         for name, value in extra.items():
-            lines.append(f"{indent}    {name}: {_safe_str(value)}\n")
+            rendered = _render_value(value)
+            if "\n" in rendered:
+                lines.append(f"{indent}    {name}:\n")
+                lines.extend(_format_block(indent, rendered))
+            else:
+                lines.append(f"{indent}    {name}: {rendered}\n")
 
         return "".join(lines)
 

testing/test_pluginmanager.py

@@ -991,7 +991,7 @@ def write(message: str) -> None:
 
     assert result == "\ud800"
     assert out == [
-        "  he_method1 [hook]\n      arg: \\ud800\n",
+        "  he_method1 [hook]\n      arg: '\\ud800'\n",
         "  finish he_method1 --> \\ud800 [hook]\n",
     ]
 

testing/test_tracer.py

@@ -1,3 +1,7 @@
+import enum
+import os
+import pathlib
+
 import pytest
 
 from pluggy import HookimplMarker
@@ -175,15 +179,53 @@ def __repr__(self) -> str:
         return "\ud800"
 
 
-def test_dictargs_keep_str_rendering(rootlogger: TagTracer) -> None:
-    """Values keep their ``str`` rendering, the trace is a log not a repr dump."""
+def test_plain_tokens_stay_bare(rootlogger: TagTracer) -> None:
+    """A value that reads unambiguously as itself is not dressed up."""
     out = rootlogger._format_message(["test"], ["call", {"name": "value", "n": 1}])
     assert out == "call [test]\n    name: value\n    n: 1\n"
 
 
+def test_whitespace_strings_are_quoted(rootlogger: TagTracer) -> None:
+    """Quotes show where a value starts and ends once it carries whitespace."""
+    out = rootlogger._format_message(["test"], ["call", {"val": " padded "}])
+    assert out == "call [test]\n    val: ' padded '\n"
+
+
+def test_empty_string_is_visible(rootlogger: TagTracer) -> None:
+    """An empty value is otherwise indistinguishable from no value at all."""
+    out = rootlogger._format_message(["test"], ["call", {"left": "", "right": "x"}])
+    assert out == "call [test]\n    left: ''\n    right: x\n"
+
+
+def test_enum_shows_member_name(rootlogger: TagTracer) -> None:
+    class Exit(enum.IntEnum):
+        FAILED = 1
+
+    out = rootlogger._format_message(["test"], ["call", {"status": Exit.FAILED}])
+    assert out == "call [test]\n    status: <Exit.FAILED: 1>\n"
+
+
+def test_pathlike_shows_its_type(rootlogger: TagTracer) -> None:
+    """Two arguments printing the same path may well be different types."""
+    out = rootlogger._format_message(
+        ["test"], ["call", {"p": pathlib.PurePosixPath("/x")}]
+    )
+    assert out == "call [test]\n    p: PurePosixPath('/x')\n"
+
+
+def test_multiline_value_is_boxed(rootlogger: TagTracer) -> None:
+    """A block stays attached to its key instead of escaping to column 0."""
+    out = rootlogger._format_message(
+        ["test"], ["call", {"expl": "first\nsecond\nthird"}]
+    )
+    assert out == (
+        "call [test]\n    expl:\n      | first\n      | second\n      \\ third\n"
+    )
+
+
 def test_dictargs_escape_surrogate_values(rootlogger: TagTracer) -> None:
     out = rootlogger._format_message(["test"], ["test", {"arg": "\ud800"}])
-    assert out == "test [test]\n    arg: \\ud800\n"
+    assert out == "test [test]\n    arg: '\\ud800'\n"
     out.encode()
 
 
@@ -289,3 +331,34 @@ def __str__(self) -> str:
 
     with pytest.raises(KeyboardInterrupt):
         rootlogger._format_message(["test"], ["test", {"arg": Broken()}])
+
+
+class BrokenPath(os.PathLike[str]):
+    """A path-like whose repr is broken, as in #424 but for a traced path."""
+
+    def __fspath__(self) -> str:
+        raise NotImplementedError("the tracer must not resolve the path")
+
+    def __repr__(self) -> str:
+        raise RuntimeError("repr is broken")
+
+
+def test_broken_repr_on_pathlike_does_not_raise(rootlogger: TagTracer) -> None:
+    out = rootlogger._format_message(["test"], ["test", {"p": BrokenPath()}])
+    assert "RuntimeError('repr is broken') raised in repr()" in out
+    assert "BrokenPath object at 0x" in out
+    out.encode()
+
+
+def test_keyboard_interrupt_from_repr_propagates(rootlogger: TagTracer) -> None:
+    """Ctrl-C while rendering a value that goes through repr still interrupts."""
+
+    class Interrupting(os.PathLike[str]):
+        def __fspath__(self) -> str:
+            raise NotImplementedError("the tracer must not resolve the path")
+
+        def __repr__(self) -> str:
+            raise KeyboardInterrupt
+
+    with pytest.raises(KeyboardInterrupt):
+        rootlogger._format_message(["test"], ["test", {"p": Interrupting()}])