Keep hook tracing from crashing on impostor values

changelog/799.bugfix.rst

@@ -0,0 +1,2 @@
+Hook tracing no longer turns a successful hook call into an error when an argument or result only claims to be a ``str`` or ``dict`` through ``__class__``, such as ``Mock(spec=str)`` (`#792 <https://github.com/pytest-dev/pluggy/issues/792>`_).
+A ``dict`` returned by a hook is now traced as the result instead of being listed as the call's arguments, and a value that fails to format is shown with its error instead of raising.

src/pluggy/_manager.py

@@ -627,7 +627,9 @@ def after(
             kwargs: Mapping[str, object],
         ) -> None:
             if outcome.exception is None:
-                hooktrace("finish", hook_name, "-->", outcome.get_result())
+                # The trailing {} ends the message: without it a dict result
+                # would be listed as if it were the call's arguments.
+                hooktrace("finish", hook_name, "-->", outcome.get_result(), {})
             hooktrace.root.indent -= 1
 
         return self.add_hookcall_monitoring(before, after)

src/pluggy/_tracing.py

@@ -9,6 +9,7 @@
 import enum
 import os
 from typing import Any
+from typing import cast
 
 
 _Writer = Callable[[str], object]
@@ -36,18 +37,26 @@ def _escape_surrogates(text: str) -> str:
     return text.encode("utf-8", "backslashreplace").decode("utf-8")
 
 
-def _safe_str(obj: object) -> str:
-    """``str(obj)`` for tracing, with a failing ``__str__`` rendered, not raised.
+def _safe(render: Callable[[object], str], obj: object, name: str) -> str:
+    """``render(obj)`` for tracing, with a failure rendered as ``name``, not raised.
 
     The result has lone surrogates escaped, so any text writer accepts it.
     """
     try:
-        text = str(obj)
+        text = render(obj)
     except Exception as exc:
-        text = _describe_failure(exc, obj, "str")
+        text = _describe_failure(exc, obj, name)
     return _escape_surrogates(text)
 
 
+def _safe_str(obj: object) -> str:
+    return _safe(str, obj, "str")
+
+
+def _safe_repr(obj: object) -> str:
+    return _safe(repr, obj, "repr")
+
+
 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
@@ -60,30 +69,19 @@ def _format_block(indent: str, lines: list[str]) -> list[str]:
 
 def _render_value(obj: object) -> str:
     """Render a traced value, adding detail only where ``str`` is ambiguous."""
+    # type(), not isinstance(): a Mock(spec=str) claims str through __class__.
+    cls = type(obj)
     # Before the str check: a StrEnum member is a str whose str() drops the name.
-    if isinstance(obj, (enum.Enum, os.PathLike)):
-        return _safe_repr(obj)
-    if isinstance(obj, str):
-        if len(obj.splitlines()) > 1:
-            return _safe_str(obj)
-        if _is_plain_token(obj):
-            return _safe_str(obj)
+    if issubclass(cls, (enum.Enum, os.PathLike)):
         return _safe_repr(obj)
+    if issubclass(cls, str):
+        text = cast(str, obj)
+        if len(text.splitlines()) > 1 or _is_plain_token(text):
+            return _safe_str(text)
+        return _safe_repr(text)
     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)
-
-
 class TagTracer:
     def __init__(self) -> None:
         self._tags2proc: dict[tuple[str, ...], _Processor] = {}
@@ -94,8 +92,8 @@ def get(self, name: str) -> TagTracerSub:
         return TagTracerSub(self, (name,))
 
     def _format_message(self, tags: Sequence[str], args: Sequence[object]) -> str:
-        if isinstance(args[-1], dict):
-            extra = args[-1]
+        if issubclass(type(args[-1]), dict):
+            extra = cast(dict[str, object], args[-1])
             args = args[:-1]
         else:
             extra = {}
@@ -106,7 +104,7 @@ def _format_message(self, tags: Sequence[str], args: Sequence[object]) -> str:
         lines = [f"{indent}{content} [{':'.join(tags)}]\n"]
 
         for name, value in extra.items():
-            rendered = _render_value(value)
+            rendered = _safe(_render_value, value, "format")
             # A bare \r is a line break too: inline, the terminal would
             # return to column 0 and overwrite the key.
             body = rendered.splitlines()

testing/test_tracer.py

@@ -1,6 +1,7 @@
 import enum
 import os
 import pathlib
+from unittest.mock import Mock
 
 import pytest
 
@@ -164,6 +165,70 @@ def hello_again(self, arg):
     ]
 
 
+class FakeStr:
+    """Claims to be a str the way a specced Mock does, through ``__class__``."""
+
+    __class__ = property(lambda self: str)
+
+    def __str__(self) -> str:
+        return "fake str"
+
+
+def echo_pm(pm: PluginManager) -> list[str]:
+    class Api:
+        @hookspec(firstresult=True)
+        def echo(self, value: object) -> object:
+            "Return the value."
+
+    class Plugin:
+        @hookimpl
+        def echo(self, value: object) -> object:
+            return value
+
+    pm.add_hookspecs(Api)
+    pm.register(Plugin())
+    trace_out: list[str] = []
+    pm.trace.root.setwriter(trace_out.append)
+    pm.enable_tracing()
+    return trace_out
+
+
+@pytest.mark.parametrize(
+    "value",
+    [Mock(spec=str), Mock(spec=dict), FakeStr()],
+    ids=["mock-spec-str", "mock-spec-dict", "fake-class-str"],
+)
+def test_tracing_impostor_value_is_traced_as_itself(
+    pm: PluginManager, value: object
+) -> None:
+    """isinstance() trusts __class__, so impostors once crashed the call (#792)."""
+    trace_out = echo_pm(pm)
+    assert pm.hook.echo(value=value) is value
+    assert trace_out == [
+        f"  echo [hook]\n      value: {value}\n",
+        f"  finish echo --> {value} [hook]\n",
+    ]
+
+
+def test_tracing_dict_result_is_not_read_as_arguments(pm: PluginManager) -> None:
+    trace_out = echo_pm(pm)
+    assert pm.hook.echo(value={"a": 1}) == {"a": 1}
+    assert trace_out == [
+        "  echo [hook]\n      value: {'a': 1}\n",
+        "  finish echo --> {'a': 1} [hook]\n",
+    ]
+
+
+def test_broken_str_subclass_value_does_not_raise(rootlogger: TagTracer) -> None:
+    class BrokenLines(str):
+        def splitlines(self, keepends: bool = False) -> list[str]:
+            raise RuntimeError("splitlines is broken")
+
+    out = rootlogger._format_message(["test"], ["test", {"arg": BrokenLines("x")}])
+    assert "RuntimeError('splitlines is broken') raised in format()" in out
+    assert "BrokenLines object at 0x" in out
+
+
 class BrokenRepr:
     def __repr__(self) -> str:
         raise RuntimeError("repr is broken")