diff --git a/changelog/799.bugfix.rst b/changelog/799.bugfix.rst new file mode 100644 index 00000000..fc2de85a --- /dev/null +++ b/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 `_). +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. diff --git a/src/pluggy/_manager.py b/src/pluggy/_manager.py index 5cddafc8..2697705b 100644 --- a/src/pluggy/_manager.py +++ b/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) diff --git a/src/pluggy/_tracing.py b/src/pluggy/_tracing.py index 9211c0b7..03fafbce 100644 --- a/src/pluggy/_tracing.py +++ b/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() diff --git a/testing/test_tracer.py b/testing/test_tracer.py index 4fc16292..b2553f13 100644 --- a/testing/test_tracer.py +++ b/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")