From 5c7823d495aaa0984ba2ba7632069504b7ccd9ec Mon Sep 17 00:00:00 2001 From: Ronny Pfannschmidt Date: Sat, 12 Sep 2026 21:27:47 +0200 Subject: [PATCH 1/7] Make hook tracing defensive about repr and surrogates Tracing could turn a working hook call into a failing one in two ways: an object whose __repr__/__str__ raises propagated that exception out of the hook call (#424), and a lone surrogate in a hook argument or return value produced a message the writer could not encode (#681). Both are now handled in one place. _safe_repr()/_safe_str() wrap the conversion the way pytest's saferepr does -- KeyboardInterrupt and SystemExit still propagate, anything else is rendered as an unpresentable-object marker -- and escape lone surrogates with backslashreplace afterwards, which also covers surrogates that come out of an object's own __repr__. Traced values -- hook kwargs and the hook result -- now use repr() so their type is visible in the log; structural labels such as the hook name and the finish/--> markers keep using str() and stay unquoted. Supersedes #627, #666, #684 and #716. Co-Authored-By: Claude Opus 5 (1M context) Co-Authored-By: Claude Code --- changelog/424.bugfix.rst | 5 +++ changelog/681.bugfix.rst | 10 +++++ docs/index.rst | 14 +++++++ src/pluggy/_manager.py | 7 +++- src/pluggy/_tracing.py | 58 +++++++++++++++++++++++++++- testing/test_pluginmanager.py | 71 +++++++++++++++++++++++++++++++++++ testing/test_tracer.py | 68 +++++++++++++++++++++++++++++++++ 7 files changed, 230 insertions(+), 3 deletions(-) create mode 100644 changelog/424.bugfix.rst create mode 100644 changelog/681.bugfix.rst diff --git a/changelog/424.bugfix.rst b/changelog/424.bugfix.rst new file mode 100644 index 00000000..7041de57 --- /dev/null +++ b/changelog/424.bugfix.rst @@ -0,0 +1,5 @@ +Tracing no longer breaks hook execution when a traced object has a broken ``__repr__`` +or ``__str__``. Such a value is now rendered as +``<[RuntimeError(...) raised in repr()] Broken object at 0x...>``, in the same style +pytest uses for unpresentable objects, instead of propagating the exception out of the +hook call. diff --git a/changelog/681.bugfix.rst b/changelog/681.bugfix.rst new file mode 100644 index 00000000..c2b91fe8 --- /dev/null +++ b/changelog/681.bugfix.rst @@ -0,0 +1,10 @@ +Tracing no longer crashes with ``UnicodeEncodeError`` when a hook argument or return +value contains lone surrogates; they are escaped with ``backslashreplace`` before the +message reaches the writer. + +As part of this, traced *values* -- the hook keyword arguments and the hook return +value -- are now formatted with ``repr()`` rather than ``str()``, so the trace output +shows ``plugin_name: 'lfplugin'`` and ``start_path: PosixPath('/x')`` instead of +``plugin_name: lfplugin`` and ``start_path: /x``. Structural labels such as the hook +name and ``finish``/``-->`` markers are unchanged. Consumers that parse +``--debug``-style trace output may need to adapt. diff --git a/docs/index.rst b/docs/index.rst index b56278ed..226728c4 100644 --- a/docs/index.rst +++ b/docs/index.rst @@ -997,6 +997,20 @@ 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] + arg: 'value' + path: PosixPath('/tmp') + finish he_method1 --> ['value'] [hook] + +Traced values are rendered with :func:`repr`, so their type stays visible, and +the rendering is defensive: an object whose ``__repr__`` raises is shown as +``<[RuntimeError(...) raised in repr()] Broken object at 0x...>``, and lone +surrogates are backslash-escaped, so enabling tracing can never turn a working +hook call into a failing one. + Call monitoring --------------- diff --git a/src/pluggy/_manager.py b/src/pluggy/_manager.py index b265aecc..4d0af3d6 100644 --- a/src/pluggy/_manager.py +++ b/src/pluggy/_manager.py @@ -595,7 +595,12 @@ def after( kwargs: Mapping[str, object], ) -> None: if outcome.exception is None: - hooktrace("finish", hook_name, "-->", outcome.get_result()) + hooktrace( + "finish", + hook_name, + "-->", + _tracing._safe_repr(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 e90418f5..6926f316 100644 --- a/src/pluggy/_tracing.py +++ b/src/pluggy/_tracing.py @@ -13,6 +13,60 @@ _Processor = Callable[[tuple[str, ...], tuple[Any, ...]], object] +def _try_repr_or_str(obj: object) -> str: + try: + return repr(obj) + except (KeyboardInterrupt, SystemExit): + raise + except BaseException: + return f'{type(obj).__name__}("{obj}")' + + +def _format_repr_exception(exc: BaseException, obj: object, func: str) -> str: + try: + exc_info = _try_repr_or_str(exc) + except (KeyboardInterrupt, SystemExit): + raise + except BaseException as inner: + exc_info = f"unpresentable exception ({_try_repr_or_str(inner)})" + name = type(obj).__name__ + return f"<[{exc_info} raised in {func}()] {name} object at 0x{id(obj):x}>" + + +def _escape_surrogates(text: str) -> str: + """Escape lone surrogates so the result survives any text writer. + + ``repr()`` passes surrogates through unchanged when they originate in an + object's own ``__repr__``, and writing such a string to a utf-8 target + raises :exc:`UnicodeEncodeError` inside the trace call. + """ + if text.isascii(): + return text + return text.encode("utf-8", "backslashreplace").decode("utf-8") + + +def _safe_str(obj: object) -> str: + """``str(obj)`` for structural trace labels, guaranteed not to raise.""" + try: + text = str(obj) + except (KeyboardInterrupt, SystemExit): + raise + except BaseException as exc: + text = _format_repr_exception(exc, obj, "str") + return _escape_surrogates(text) + + +def _safe_repr(obj: object) -> str: + """``repr(obj)`` for traced values, guaranteed not to raise.""" + try: + text = repr(obj) + except (KeyboardInterrupt, SystemExit): + raise + except BaseException as exc: + text = _format_repr_exception(exc, obj, "repr") + return _escape_surrogates(text) + + class TagTracer: def __init__(self) -> None: self._tags2proc: dict[tuple[str, ...], _Processor] = {} @@ -29,13 +83,13 @@ def _format_message(self, tags: Sequence[str], args: Sequence[object]) -> str: else: extra = {} - content = " ".join(map(str, args)) + content = " ".join(map(_safe_str, args)) indent = " " * self.indent lines = [f"{indent}{content} [{':'.join(tags)}]\n"] for name, value in extra.items(): - lines.append(f"{indent} {name}: {value}\n") + lines.append(f"{indent} {name}: {_safe_repr(value)}\n") return "".join(lines) diff --git a/testing/test_pluginmanager.py b/testing/test_pluginmanager.py index 43c2f73a..6770e275 100644 --- a/testing/test_pluginmanager.py +++ b/testing/test_pluginmanager.py @@ -912,6 +912,77 @@ def he_method1(self): undo() +def test_hook_tracing_escapes_surrogate_values(pm: PluginManager) -> None: + """Surrogates in traced arguments and results never reach the writer. + + Regression test for #681 (pytest-dev/pytest#13750). + """ + + class Hooks: + @hookspec(firstresult=True) + def he_method1(self, arg: object) -> object: + raise NotImplementedError() + + class Plugin: + @hookimpl + def he_method1(self, arg: object) -> object: + return arg + + out: list[str] = [] + + def write(message: str) -> None: + message.encode() + out.append(message) + + pm.add_hookspecs(Hooks) + pm.register(Plugin()) + pm.trace.root.setwriter(write) + undo = pm.enable_tracing() + try: + result = pm.hook.he_method1(arg="\ud800") + finally: + undo() + + assert result == "\ud800" + assert out == [ + " he_method1 [hook]\n arg: '\\ud800'\n", + " finish he_method1 --> '\\ud800' [hook]\n", + ] + + +def test_hook_tracing_with_broken_repr(he_pm: PluginManager) -> None: + """A broken ``__repr__`` does not break the hook call. + + Regression test for #424 (kedro-org/kedro#2630). + """ + + class BrokenRepr: + def __repr__(self) -> str: + raise RuntimeError("repr is broken") + + class api1: + @hookimpl + def he_method1(self, arg): + return arg + + he_pm.register(api1()) + out: list[str] = [] + he_pm.trace.root.setwriter(out.append) + undo = he_pm.enable_tracing() + arg = BrokenRepr() + try: + result = he_pm.hook.he_method1(arg=arg) + finally: + undo() + + assert result == [arg] + assert len(out) == 2 + assert "he_method1" in out[0] + assert "RuntimeError('repr is broken') raised in repr()" in out[0] + assert "BrokenRepr object at 0x" in out[0] + assert "finish" in out[1] + + @pytest.mark.parametrize("historic", [False, True]) def test_register_while_calling( pm: PluginManager, diff --git a/testing/test_tracer.py b/testing/test_tracer.py index 13b29721..db968ae8 100644 --- a/testing/test_tracer.py +++ b/testing/test_tracer.py @@ -158,3 +158,71 @@ def hello_again(self, arg): " hello [hook]\n arg: 3\n", " finish hello --> [] [hook]\n", ] +class BrokenRepr: + def __repr__(self) -> str: + raise RuntimeError("repr is broken") + + +class BrokenStr: + def __repr__(self) -> str: + return "BrokenStr()" + + def __str__(self) -> str: + raise RuntimeError("str is broken") + + +class SurrogateRepr: + def __repr__(self) -> str: + return "\ud800" + + +def test_dictargs_use_repr(rootlogger: TagTracer) -> None: + """Traced values are repred so their type is visible in the log.""" + out = rootlogger._format_message(["test"], ["call", {"name": "value", "n": 1}]) + assert out == "call [test]\n name: 'value'\n n: 1\n" + + +def test_labels_are_not_repred(rootlogger: TagTracer) -> None: + """Structural labels stay unquoted, only values are repred.""" + out = rootlogger._format_message(["test"], ["finish", "he_method1", "-->", "[]"]) + assert out == "finish he_method1 --> [] [test]\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" + out.encode() + + +def test_escape_surrogates_from_repr(rootlogger: TagTracer) -> None: + """A surrogate coming out of the object's own repr is escaped too.""" + out = rootlogger._format_message(["test"], ["test", {"arg": SurrogateRepr()}]) + assert out == "test [test]\n arg: \\ud800\n" + out.encode() + + +def test_escape_surrogates_in_labels(rootlogger: TagTracer) -> None: + out = rootlogger._format_message(["test"], ["\ud800"]) + assert out == "\\ud800 [test]\n" + out.encode() + + +def test_non_ascii_values_are_kept(rootlogger: TagTracer) -> None: + """Legible text is not mangled, only lone surrogates are escaped.""" + out = rootlogger._format_message(["test"], ["héllo", {"arg": "wörld"}]) + assert out == "héllo [test]\n arg: 'wörld'\n" + out.encode() + + +def test_broken_repr_value_does_not_raise(rootlogger: TagTracer) -> None: + out = rootlogger._format_message(["test"], ["test", {"arg": BrokenRepr()}]) + assert "RuntimeError('repr is broken') raised in repr()" in out + assert "BrokenRepr object at 0x" in out + out.encode() + + +def test_broken_str_label_does_not_raise(rootlogger: TagTracer) -> None: + out = rootlogger._format_message(["test"], [BrokenStr()]) + assert "RuntimeError('str is broken') raised in str()" in out + assert "BrokenStr object at 0x" in out + out.encode() From d2bf2846cdf0c5b244aac3fac48c31e11fa3ac1f Mon Sep 17 00:00:00 2001 From: Ronny Pfannschmidt Date: Sat, 12 Sep 2026 21:36:39 +0200 Subject: [PATCH 2/7] Keep trace output str-based The previous commit also switched traced values from str() to repr(), following the design distilled in #681. That is a user visible change to pytest's --debug output, and it makes that output worse to read. The worst case is a value that is meant to be read as a block. With enable_assertion_pass_hook, pytest passes the assertion explanation to pytest_assertion_pass as a multi line string. Under str() the trace shows it as written: expl: {'x': [0, 1, ...} == {'x': [0, 1, ...} Omitting 2 identical items, use -vv to show Use -v to get more diff Under repr() the same value becomes one escaped line: expl: "{'x': [0, 1, ...} == {'x': [0, 1, ...}\n \n Omitting 2 identical items, use -vv to show\n Use -v to get more diff" The rest is quieter but hits every run: of 439 traced kwarg values in a real pytest --debug run, 123 render differently, and 115 of those are nothing but quotes added around strings that were already readable -- every plugin registration line turns plugin_name: lfplugin into a quoted string. 105 of the 674 lines in the sampled trace change, so anything parsing that output breaks as well. The trace is pytest UX. A fix for a crash that nobody hits in normal use must not degrade the daily reading experience of everyone who does not hit it. The cases where repr() genuinely helps are real -- PosixPath vs py.path.local for two arguments that print the same path, ExitCode vs a bare int -- but they are 15 lines out of 674, and they do not pay for the other 115 plus the escaped blocks. The crash fixes never depended on repr(): _safe_str() guards the conversion and escapes lone surrogates just as well, so #424 and #681 stay fixed while pytest --debug output is byte for byte what it was before (verified: 674 trace lines, 0 differences). The type visibility idea is not rejected, only unbundled -- it can be argued on its own in #681, as a deliberate output change with its own changelog entry. Co-Authored-By: Claude Opus 5 (1M context) Co-Authored-By: Claude Code --- changelog/681.bugfix.rst | 9 +-------- docs/index.rst | 10 +++++----- src/pluggy/_manager.py | 7 +------ src/pluggy/_tracing.py | 32 +++++++++++++------------------- testing/test_pluginmanager.py | 6 +++--- testing/test_tracer.py | 18 ++++++------------ 6 files changed, 29 insertions(+), 53 deletions(-) diff --git a/changelog/681.bugfix.rst b/changelog/681.bugfix.rst index c2b91fe8..f2d94a4c 100644 --- a/changelog/681.bugfix.rst +++ b/changelog/681.bugfix.rst @@ -1,10 +1,3 @@ Tracing no longer crashes with ``UnicodeEncodeError`` when a hook argument or return value contains lone surrogates; they are escaped with ``backslashreplace`` before the -message reaches the writer. - -As part of this, traced *values* -- the hook keyword arguments and the hook return -value -- are now formatted with ``repr()`` rather than ``str()``, so the trace output -shows ``plugin_name: 'lfplugin'`` and ``start_path: PosixPath('/x')`` instead of -``plugin_name: lfplugin`` and ``start_path: /x``. Structural labels such as the hook -name and ``finish``/``-->`` markers are unchanged. Consumers that parse -``--debug``-style trace output may need to adapt. +message reaches the writer. Trace output is otherwise unchanged. diff --git a/docs/index.rst b/docs/index.rst index 226728c4..85f9ea4c 100644 --- a/docs/index.rst +++ b/docs/index.rst @@ -1001,13 +1001,13 @@ Each hook call is traced with its keyword arguments, followed by a ``finish`` line carrying the result:: he_method1 [hook] - arg: 'value' - path: PosixPath('/tmp') + arg: value + path: /tmp finish he_method1 --> ['value'] [hook] -Traced values are rendered with :func:`repr`, so their type stays visible, and -the rendering is defensive: an object whose ``__repr__`` raises is shown as -``<[RuntimeError(...) raised in repr()] Broken object at 0x...>``, and lone +Values are rendered with :func:`str`, and the rendering is defensive: an object +whose ``__str__`` raises is shown as +``<[RuntimeError(...) raised in str()] Broken object at 0x...>``, and lone surrogates are backslash-escaped, so enabling tracing can never turn a working hook call into a failing one. diff --git a/src/pluggy/_manager.py b/src/pluggy/_manager.py index 4d0af3d6..b265aecc 100644 --- a/src/pluggy/_manager.py +++ b/src/pluggy/_manager.py @@ -595,12 +595,7 @@ def after( kwargs: Mapping[str, object], ) -> None: if outcome.exception is None: - hooktrace( - "finish", - hook_name, - "-->", - _tracing._safe_repr(outcome.get_result()), - ) + 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 6926f316..100fd792 100644 --- a/src/pluggy/_tracing.py +++ b/src/pluggy/_tracing.py @@ -22,7 +22,7 @@ def _try_repr_or_str(obj: object) -> str: return f'{type(obj).__name__}("{obj}")' -def _format_repr_exception(exc: BaseException, obj: object, func: str) -> str: +def _format_str_exception(exc: BaseException, obj: object) -> str: try: exc_info = _try_repr_or_str(exc) except (KeyboardInterrupt, SystemExit): @@ -30,15 +30,15 @@ def _format_repr_exception(exc: BaseException, obj: object, func: str) -> str: except BaseException as inner: exc_info = f"unpresentable exception ({_try_repr_or_str(inner)})" name = type(obj).__name__ - return f"<[{exc_info} raised in {func}()] {name} object at 0x{id(obj):x}>" + return f"<[{exc_info} raised in str()] {name} object at 0x{id(obj):x}>" def _escape_surrogates(text: str) -> str: """Escape lone surrogates so the result survives any text writer. - ``repr()`` passes surrogates through unchanged when they originate in an - object's own ``__repr__``, and writing such a string to a utf-8 target - raises :exc:`UnicodeEncodeError` inside the trace call. + A lone surrogate reaching the writer raises :exc:`UnicodeEncodeError` + inside the trace call for any utf-8 target, such as the file behind + pytest's ``--debug``. """ if text.isascii(): return text @@ -46,24 +46,18 @@ def _escape_surrogates(text: str) -> str: def _safe_str(obj: object) -> str: - """``str(obj)`` for structural trace labels, guaranteed not to raise.""" - try: - text = str(obj) - except (KeyboardInterrupt, SystemExit): - raise - except BaseException as exc: - text = _format_repr_exception(exc, obj, "str") - return _escape_surrogates(text) - + """``str(obj)`` for tracing, guaranteed not to raise and always writable. -def _safe_repr(obj: object) -> str: - """``repr(obj)`` for traced values, guaranteed not to raise.""" + Tracing is a debugging aid, so it must never be the reason a hook call + fails, and the rendering stays ``str``-based to keep the trace output + readable. + """ try: - text = repr(obj) + text = str(obj) except (KeyboardInterrupt, SystemExit): raise except BaseException as exc: - text = _format_repr_exception(exc, obj, "repr") + text = _format_str_exception(exc, obj) return _escape_surrogates(text) @@ -89,7 +83,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(): - lines.append(f"{indent} {name}: {_safe_repr(value)}\n") + lines.append(f"{indent} {name}: {_safe_str(value)}\n") return "".join(lines) diff --git a/testing/test_pluginmanager.py b/testing/test_pluginmanager.py index 6770e275..a5138abf 100644 --- a/testing/test_pluginmanager.py +++ b/testing/test_pluginmanager.py @@ -945,8 +945,8 @@ def write(message: str) -> None: assert result == "\ud800" assert out == [ - " he_method1 [hook]\n arg: '\\ud800'\n", - " finish he_method1 --> '\\ud800' [hook]\n", + " he_method1 [hook]\n arg: \\ud800\n", + " finish he_method1 --> \\ud800 [hook]\n", ] @@ -978,7 +978,7 @@ def he_method1(self, arg): assert result == [arg] assert len(out) == 2 assert "he_method1" in out[0] - assert "RuntimeError('repr is broken') raised in repr()" in out[0] + assert "RuntimeError('repr is broken') raised in str()" in out[0] assert "BrokenRepr object at 0x" in out[0] assert "finish" in out[1] diff --git a/testing/test_tracer.py b/testing/test_tracer.py index db968ae8..c9e049e3 100644 --- a/testing/test_tracer.py +++ b/testing/test_tracer.py @@ -176,21 +176,15 @@ def __repr__(self) -> str: return "\ud800" -def test_dictargs_use_repr(rootlogger: TagTracer) -> None: - """Traced values are repred so their type is visible in the log.""" +def test_dictargs_keep_str_rendering(rootlogger: TagTracer) -> None: + """Values keep their ``str`` rendering, the trace is a log not a repr dump.""" out = rootlogger._format_message(["test"], ["call", {"name": "value", "n": 1}]) - assert out == "call [test]\n name: 'value'\n n: 1\n" - - -def test_labels_are_not_repred(rootlogger: TagTracer) -> None: - """Structural labels stay unquoted, only values are repred.""" - out = rootlogger._format_message(["test"], ["finish", "he_method1", "-->", "[]"]) - assert out == "finish he_method1 --> [] [test]\n" + assert out == "call [test]\n name: value\n n: 1\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() @@ -210,13 +204,13 @@ def test_escape_surrogates_in_labels(rootlogger: TagTracer) -> None: def test_non_ascii_values_are_kept(rootlogger: TagTracer) -> None: """Legible text is not mangled, only lone surrogates are escaped.""" out = rootlogger._format_message(["test"], ["héllo", {"arg": "wörld"}]) - assert out == "héllo [test]\n arg: 'wörld'\n" + assert out == "héllo [test]\n arg: wörld\n" out.encode() def test_broken_repr_value_does_not_raise(rootlogger: TagTracer) -> None: out = rootlogger._format_message(["test"], ["test", {"arg": BrokenRepr()}]) - assert "RuntimeError('repr is broken') raised in repr()" in out + assert "RuntimeError('repr is broken') raised in str()" in out assert "BrokenRepr object at 0x" in out out.encode() From 4057d7e99e8f772be118bdef126f376e4e41459f Mon Sep 17 00:00:00 2001 From: Ronny Pfannschmidt Date: Sat, 12 Sep 2026 22:45:23 +0200 Subject: [PATCH 3/7] Cover the unpresentable object paths in tracing The guards around str() were only exercised for the simple case of a broken __str__. The exception explaining that failure can be just as broken, and Ctrl-C has to stay reliable at both levels, so cover: an exception whose repr fails, an exception whose repr and str both fail, and KeyboardInterrupt raised from the value and from the explanation. _tracing.py is at 100% statement and branch coverage. Co-Authored-By: Claude Opus 5 (1M context) Co-Authored-By: Claude Code --- testing/test_tracer.py | 66 ++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 66 insertions(+) diff --git a/testing/test_tracer.py b/testing/test_tracer.py index c9e049e3..8c77a7cb 100644 --- a/testing/test_tracer.py +++ b/testing/test_tracer.py @@ -220,3 +220,69 @@ def test_broken_str_label_does_not_raise(rootlogger: TagTracer) -> None: assert "RuntimeError('str is broken') raised in str()" in out assert "BrokenStr object at 0x" in out out.encode() + + +def test_keyboard_interrupt_from_str_propagates(rootlogger: TagTracer) -> None: + """Ctrl-C during a traced call still interrupts, it is not swallowed.""" + + class Interrupting: + def __str__(self) -> str: + raise KeyboardInterrupt + + with pytest.raises(KeyboardInterrupt): + rootlogger._format_message(["test"], ["test", {"arg": Interrupting()}]) + + +def test_broken_exception_repr_is_handled(rootlogger: TagTracer) -> None: + """The exception explaining the failure may itself be unpresentable.""" + + class BadError(Exception): + def __repr__(self) -> str: + raise RuntimeError("exception repr is broken") + + def __str__(self) -> str: + return "readable message" + + class Broken: + def __str__(self) -> str: + raise BadError + + out = rootlogger._format_message(["test"], ["test", {"arg": Broken()}]) + assert 'BadError("readable message") raised in str()' in out + assert "Broken object at 0x" in out + + +def test_unpresentable_exception_is_handled(rootlogger: TagTracer) -> None: + """Neither repr nor str of the exception works, and tracing still survives.""" + + class UnpresentableError(Exception): + def __repr__(self) -> str: + raise RuntimeError("exception repr is broken") + + def __str__(self) -> str: + raise RuntimeError("exception str is broken") + + class Broken: + def __str__(self) -> str: + raise UnpresentableError + + out = rootlogger._format_message(["test"], ["test", {"arg": Broken()}]) + assert "unpresentable exception (RuntimeError('exception str is broken'))" in out + assert "Broken object at 0x" in out + + +def test_keyboard_interrupt_from_exception_repr_propagates( + rootlogger: TagTracer, +) -> None: + """Ctrl-C while rendering the failure explanation propagates as well.""" + + class InterruptingError(Exception): + def __repr__(self) -> str: + raise KeyboardInterrupt + + class Broken: + def __str__(self) -> str: + raise InterruptingError + + with pytest.raises(KeyboardInterrupt): + rootlogger._format_message(["test"], ["test", {"arg": Broken()}]) From b7910c19d841efe85cf46bad9cc066ec0c4880e2 Mon Sep 17 00:00:00 2001 From: Ronny Pfannschmidt Date: Sat, 12 Sep 2026 22:50:44 +0200 Subject: [PATCH 4/7] Drop an unused repr from a tracing test double BrokenStr's __repr__ was never called -- _safe_str reaches for __str__, and the failure message is built from the type name -- so it only showed up as an uncovered line. Co-Authored-By: Claude Opus 5 (1M context) Co-Authored-By: Claude Code --- testing/test_tracer.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/testing/test_tracer.py b/testing/test_tracer.py index 8c77a7cb..ed205abe 100644 --- a/testing/test_tracer.py +++ b/testing/test_tracer.py @@ -158,15 +158,14 @@ def hello_again(self, arg): " hello [hook]\n arg: 3\n", " finish hello --> [] [hook]\n", ] + + class BrokenRepr: def __repr__(self) -> str: raise RuntimeError("repr is broken") class BrokenStr: - def __repr__(self) -> str: - return "BrokenStr()" - def __str__(self) -> str: raise RuntimeError("str is broken") From e7d2456b38b769a96911985caf7dcebad25341fd Mon Sep 17 00:00:00 2001 From: Ronny Pfannschmidt Date: Sat, 12 Sep 2026 22:40:30 +0200 Subject: [PATCH 5/7] Add detail to traced values where str() is ambiguous Trace output stays str() based, because that is what makes it readable, but str() hides things a reader needs often enough to be worth fixing case by case: - an empty string is indistinguishable from no value at all, which is exactly wrong for a comparison trace showing left and right - a string carrying whitespace has no visible boundaries - an IntEnum prints as a bare number, losing the member name - a path prints as text, so a PosixPath and a py.path.local argument pointing at the same place look identical - a multi line value runs into column 0 and reads as a trace line of its own rather than as the value of its key So values that read unambiguously as themselves -- a non empty printable string without spaces, and every type whose repr adds nothing -- stay bare, and the rest gain quotes, their type, or a block. Multi line values are drawn as a box, each line prefixed with | and the last with \\, so the extent of the value is visible at a glance. Measured on a real pytest --debug run, this changes 45 of 1329 trace lines, against 216 for rendering every value with repr(). Every changed line carries information the previous rendering dropped. Builds on #728, which must land first. Co-Authored-By: Claude Opus 5 (1M context) Co-Authored-By: Claude Code --- docs/index.rst | 18 +++++++--- src/pluggy/_tracing.py | 62 ++++++++++++++++++++++++++++++++--- testing/test_pluginmanager.py | 2 +- testing/test_tracer.py | 47 ++++++++++++++++++++++++-- 4 files changed, 117 insertions(+), 12 deletions(-) diff --git a/docs/index.rst b/docs/index.rst index 85f9ea4c..d0bfaf41 100644 --- a/docs/index.rst +++ b/docs/index.rst @@ -1001,12 +1001,22 @@ Each hook call is traced with its keyword arguments, followed by a ``finish`` line carrying the result:: he_method1 [hook] - arg: value - path: /tmp + plugin_name: example + path: PosixPath('/tmp') + reason: 'needs a network connection' + status: + explanation: + | first line + \ second line finish he_method1 --> ['value'] [hook] -Values are rendered with :func:`str`, and the rendering is defensive: an object -whose ``__str__`` raises is shown as +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. + +The rendering is also defensive: an object whose ``__str__`` raises is shown as ``<[RuntimeError(...) raised in str()] Broken object at 0x...>``, and lone surrogates are backslash-escaped, so enabling tracing can never turn a working hook call into a failing one. diff --git a/src/pluggy/_tracing.py b/src/pluggy/_tracing.py index 100fd792..46153b02 100644 --- a/src/pluggy/_tracing.py +++ b/src/pluggy/_tracing.py @@ -6,6 +6,8 @@ from collections.abc import Callable from collections.abc import Sequence +import enum +import os from typing import Any @@ -22,7 +24,7 @@ def _try_repr_or_str(obj: object) -> str: return f'{type(obj).__name__}("{obj}")' -def _format_str_exception(exc: BaseException, obj: object) -> str: +def _format_conversion_exception(exc: BaseException, obj: object, func: str) -> str: try: exc_info = _try_repr_or_str(exc) except (KeyboardInterrupt, SystemExit): @@ -30,7 +32,7 @@ def _format_str_exception(exc: BaseException, obj: object) -> str: except BaseException as inner: exc_info = f"unpresentable exception ({_try_repr_or_str(inner)})" 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: @@ -57,7 +59,54 @@ def _safe_str(obj: object) -> str: except (KeyboardInterrupt, SystemExit): raise except BaseException as exc: - text = _format_str_exception(exc, obj) + text = _format_conversion_exception(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, guaranteed not to raise and always writable.""" + try: + text = repr(obj) + except (KeyboardInterrupt, SystemExit): + raise + except BaseException as exc: + text = _format_conversion_exception(exc, obj, "repr") return _escape_surrogates(text) @@ -83,7 +132,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) diff --git a/testing/test_pluginmanager.py b/testing/test_pluginmanager.py index a5138abf..0bacb5c1 100644 --- a/testing/test_pluginmanager.py +++ b/testing/test_pluginmanager.py @@ -945,7 +945,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", ] diff --git a/testing/test_tracer.py b/testing/test_tracer.py index ed205abe..4d66a91c 100644 --- a/testing/test_tracer.py +++ b/testing/test_tracer.py @@ -1,3 +1,6 @@ +import enum +import pathlib + import pytest from pluggy import HookimplMarker @@ -175,15 +178,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: \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() From c6ff663f77ce36352b880987ff17dfacb453a34a Mon Sep 17 00:00:00 2001 From: Ronny Pfannschmidt Date: Sat, 12 Sep 2026 22:40:56 +0200 Subject: [PATCH 6/7] Add changelog fragment for the traced value rendering Co-Authored-By: Claude Opus 5 (1M context) Co-Authored-By: Claude Code --- changelog/729.feature.rst | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 changelog/729.feature.rst diff --git a/changelog/729.feature.rst b/changelog/729.feature.rst new file mode 100644 index 00000000..842fa1e1 --- /dev/null +++ b/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. From 6015a75f968b923c981504e518e7b86037721fd9 Mon Sep 17 00:00:00 2001 From: Ronny Pfannschmidt Date: Sat, 12 Sep 2026 22:46:07 +0200 Subject: [PATCH 7/7] Cover the repr guards added for traced values _safe_repr is only reached for enums, paths and quoted strings, which all have working reprs in the existing tests, so its guards were dead in coverage. A path-like with a broken repr is the #424 scenario applied to a value the heuristic sends through repr. _tracing.py is back at 100% statement and branch coverage. Co-Authored-By: Claude Opus 5 (1M context) Co-Authored-By: Claude Code --- testing/test_tracer.py | 32 ++++++++++++++++++++++++++++++++ 1 file changed, 32 insertions(+) diff --git a/testing/test_tracer.py b/testing/test_tracer.py index 4d66a91c..4bd5f4a1 100644 --- a/testing/test_tracer.py +++ b/testing/test_tracer.py @@ -1,4 +1,5 @@ import enum +import os import pathlib import pytest @@ -326,3 +327,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()}])