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..f2d94a4c --- /dev/null +++ b/changelog/681.bugfix.rst @@ -0,0 +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. Trace output is otherwise unchanged. 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. diff --git a/docs/index.rst b/docs/index.rst index b56278ed..d0bfaf41 100644 --- a/docs/index.rst +++ b/docs/index.rst @@ -997,6 +997,30 @@ 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: + 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. + +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. + Call monitoring --------------- diff --git a/src/pluggy/_tracing.py b/src/pluggy/_tracing.py index e90418f5..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 @@ -13,6 +15,101 @@ _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_conversion_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. + + 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 + return text.encode("utf-8", "backslashreplace").decode("utf-8") + + +def _safe_str(obj: object) -> str: + """``str(obj)`` for tracing, guaranteed not to raise and always writable. + + 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 = str(obj) + except (KeyboardInterrupt, SystemExit): + raise + except BaseException as exc: + 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) + + class TagTracer: def __init__(self) -> None: self._tags2proc: dict[tuple[str, ...], _Processor] = {} @@ -29,13 +126,18 @@ 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") + 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 43c2f73a..0bacb5c1 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 str()" 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..4bd5f4a1 100644 --- a/testing/test_tracer.py +++ b/testing/test_tracer.py @@ -1,3 +1,7 @@ +import enum +import os +import pathlib + import pytest from pluggy import HookimplMarker @@ -158,3 +162,199 @@ 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 __str__(self) -> str: + raise RuntimeError("str is broken") + + +class SurrogateRepr: + def __repr__(self) -> str: + return "\ud800" + + +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" + 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 str()" 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() + + +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()}]) + + +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()}])