From fa5f99c4e07bed828939c378e78e9354ca308828 Mon Sep 17 00:00:00 2001 From: Ahmed Allam Date: Sun, 4 Oct 2026 05:24:34 +0000 Subject: [PATCH] fix(telemetry): route every unraisable and thread exception to strix.log, never stderr Completes the previous commit, which only carried the test rename. sys.unraisablehook (finalizers, __del__, GC and weakref callbacks, files closed at exit) and threading.excepthook are replaced for the life of the process with hooks that log the report at WARNING on strix.telemetry: strix.log, and stderr only when the stream handler runs at DEBUG (STRIX_DEBUG=1). Nothing is delegated to Python's default printers; a report arriving after the strix handlers are torn down is dropped instead of reaching logging.lastResort, and failures inside logging itself are swallowed. --- strix/telemetry/logging.py | 92 +++++---- tests/test_hook_exceptions_logged.py | 266 ++++++++++++++++++--------- 2 files changed, 239 insertions(+), 119 deletions(-) diff --git a/strix/telemetry/logging.py b/strix/telemetry/logging.py index 3ebd91fd..0e4dc7f2 100644 --- a/strix/telemetry/logging.py +++ b/strix/telemetry/logging.py @@ -5,8 +5,9 @@ from __future__ import annotations import contextlib import logging import os -import re import sys +import threading +import traceback import warnings from contextvars import ContextVar from pathlib import Path # noqa: TC003 used at runtime by ``setup_scan_logging`` @@ -15,6 +16,7 @@ from typing import TYPE_CHECKING if TYPE_CHECKING: from collections.abc import Callable + from types import TracebackType _SCAN_ID: ContextVar[str | None] = ContextVar("strix_scan_id", default=None) @@ -89,52 +91,76 @@ def configure_dependency_logging() -> None: logging.getLogger("asyncio").setLevel(logging.CRITICAL) logging.getLogger("asyncio").propagate = False warnings.filterwarnings("ignore", category=RuntimeWarning, module="asyncio") - _silence_urllib3_finalizer_noise() + _route_hook_exceptions_to_log() -_unraisable_hook_installed = False +_hooks_installed = False -_FINALIZER_FILE_RE = re.compile(r"finalizing file <(urllib3|http\.client)\.") +def _format_exception( + exc_type: type[BaseException] | None, + exc_value: BaseException | None, + exc_traceback: TracebackType | None, +) -> str: + if exc_value is None and exc_type is None: + return "-" + return "".join(traceback.format_exception(exc_type, exc_value, exc_traceback)).rstrip() -def _is_urllib3_closed_file_noise(unraisable: sys.UnraisableHookArgs) -> bool: - """An HTTP response (urllib3 or http.client) whose socket was closed first. +def _log_quietly(message: str, *args: object) -> None: + """Write a WARNING to the strix log; never let it reach the terminal. - Python 3.14 reports IOBase finalizer failures with ``object=None`` and the - object's repr inside ``err_msg`` ("Exception ignored while finalizing file - <...>"); earlier versions pass the object itself. + Dropped (not printed) when the strix logger tree has no handler, which + is the case after scan teardown: ``logging.lastResort`` would otherwise + print it to stderr. The interpreter may be finalizing, so any failure + inside logging itself is swallowed too. """ - if not ( - isinstance(unraisable.exc_value, ValueError) - and "I/O operation on closed file" in str(unraisable.exc_value) - ): - return False - if unraisable.object is not None: - module = type(unraisable.object).__module__ - return module.split(".")[0] == "urllib3" or module == "http.client" - return _FINALIZER_FILE_RE.search(unraisable.err_msg or "") is not None + with contextlib.suppress(BaseException): + logger = logging.getLogger("strix.telemetry") + if logger.hasHandlers(): + logger.warning(message, *args) -def _silence_urllib3_finalizer_noise() -> None: - global _unraisable_hook_installed # noqa: PLW0603 - if _unraisable_hook_installed: +def _route_hook_exceptions_to_log() -> None: + """Keep "Exception ignored in ..." reports and thread tracebacks off the terminal. + + Python's default ``sys.unraisablehook`` (finalizers, ``__del__``, GC and + weakref callbacks, buffered-file close at exit) and + ``threading.excepthook`` (uncaught exceptions in threads) print a + traceback to stderr, which lands in the terminal after the scan summary. + Both are replaced, for the life of the process, with hooks that log the + report at WARNING on ``strix.telemetry`` instead: it goes to strix.log, + and to stderr only when the stream handler runs at DEBUG (STRIX_DEBUG=1). + """ + global _hooks_installed # noqa: PLW0603 + if _hooks_installed: return - _unraisable_hook_installed = True - previous = sys.unraisablehook + _hooks_installed = True - def hook(unraisable: sys.UnraisableHookArgs) -> None: - if _is_urllib3_closed_file_noise(unraisable): - with contextlib.suppress(Exception): # the interpreter may be finalizing - logging.getLogger("strix.telemetry").debug( - "Ignored HTTP response finalizer error: %s: %s", - unraisable.err_msg or type(unraisable.object).__name__, - unraisable.exc_value, - ) + def unraisable_hook(unraisable: sys.UnraisableHookArgs) -> None: + with contextlib.suppress(BaseException): + subject = unraisable.err_msg or f"Exception ignored in {unraisable.object!r}" + _log_quietly( + "%s\n%s", + subject, + _format_exception( + unraisable.exc_type, unraisable.exc_value, unraisable.exc_traceback + ), + ) + + def thread_hook(args: threading.ExceptHookArgs) -> None: + if args.exc_type is SystemExit: return - previous(unraisable) + with contextlib.suppress(BaseException): + name = args.thread.name if args.thread is not None else "-" + _log_quietly( + "Exception in thread %s\n%s", + name, + _format_exception(args.exc_type, args.exc_value, args.exc_traceback), + ) - sys.unraisablehook = hook + sys.unraisablehook = unraisable_hook + threading.excepthook = thread_hook class _CurrentStderrHandler(logging.StreamHandler): # type: ignore[type-arg] diff --git a/tests/test_hook_exceptions_logged.py b/tests/test_hook_exceptions_logged.py index 690629e6..06610451 100644 --- a/tests/test_hook_exceptions_logged.py +++ b/tests/test_hook_exceptions_logged.py @@ -1,112 +1,206 @@ -import http.client -import http.cookiejar -import socket +"""Nothing from sys.unraisablehook or threading.excepthook reaches the terminal. + +Python prints "Exception ignored in ..." reports (finalizers, ``__del__``, GC +and weakref callbacks, files closed at interpreter exit) and uncaught thread +exceptions straight to stderr. Strix routes both to its own logger instead, +so they end up in strix.log (and on stderr only under STRIX_DEBUG=1). +""" + +from __future__ import annotations + +import logging +import os +import subprocess import sys +import threading +from pathlib import Path +from types import SimpleNamespace +from typing import TYPE_CHECKING import pytest -import urllib3.response from strix.telemetry import logging as tlog -from strix.telemetry.logging import _is_urllib3_closed_file_noise -class _Args: - def __init__( - self, exc_value: BaseException | None, obj: object, err_msg: str | None = None - ) -> None: - self.exc_type = type(exc_value) if exc_value is not None else None - self.exc_value = exc_value - self.exc_traceback = None - self.err_msg = err_msg - self.object = obj +if TYPE_CHECKING: + from collections.abc import Iterator -def _urllib3_response() -> urllib3.response.HTTPResponse: - return urllib3.response.HTTPResponse(body=b"") +def _unraisable(exc: BaseException, obj: object, err_msg: str | None = None) -> object: + return SimpleNamespace( + exc_type=type(exc), + exc_value=exc, + exc_traceback=None, + err_msg=err_msg, + object=obj, + ) -def test_filters_urllib3_closed_file_noise() -> None: - args = _Args(ValueError("I/O operation on closed file."), _urllib3_response()) - assert _is_urllib3_closed_file_noise(args) # type: ignore[arg-type] +@pytest.fixture +def strix_records() -> Iterator[list[logging.LogRecord]]: + records: list[logging.LogRecord] = [] + class _Collect(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + records.append(record) -def test_ignores_closed_file_errors_from_other_http_modules() -> None: - args = _Args(ValueError("I/O operation on closed file."), http.cookiejar.CookieJar()) - assert not _is_urllib3_closed_file_noise(args) # type: ignore[arg-type] - - -def test_filters_http_client_closed_file_noise() -> None: - sock = socket.socket() + handler = _Collect() + root = logging.getLogger("strix") + root.addHandler(handler) try: - response = http.client.HTTPResponse(sock) + yield records finally: - sock.close() - args = _Args(ValueError("I/O operation on closed file."), response) - assert _is_urllib3_closed_file_noise(args) # type: ignore[arg-type] + root.removeHandler(handler) + + +@pytest.fixture +def hooks(monkeypatch: pytest.MonkeyPatch) -> tuple[list[object], list[object]]: + """Install strix's hooks over recording stand-ins for Python's defaults.""" + unraisable_calls: list[object] = [] + thread_calls: list[object] = [] + monkeypatch.setattr(sys, "unraisablehook", unraisable_calls.append) + monkeypatch.setattr(threading, "excepthook", thread_calls.append) + monkeypatch.setattr(tlog, "_hooks_installed", False) + tlog.configure_dependency_logging() + return unraisable_calls, thread_calls @pytest.mark.parametrize( - "repr_text", + "args", [ - "", - "", - ], -) -def test_filters_python314_finalizer_shape(repr_text: str) -> None: - """3.14 reports IOBase finalizer failures with object=None and the repr in err_msg.""" - args = _Args( - ValueError("I/O operation on closed file."), - None, - err_msg=f"Exception ignored while finalizing file {repr_text}", - ) - assert _is_urllib3_closed_file_noise(args) # type: ignore[arg-type] - - -def test_python314_shape_passes_through_other_files() -> None: - args = _Args( - ValueError("I/O operation on closed file."), - None, - err_msg="Exception ignored while finalizing file <_io.TextIOWrapper name='x' mode='w'>", - ) - assert not _is_urllib3_closed_file_noise(args) # type: ignore[arg-type] - assert not _is_urllib3_closed_file_noise( - _Args(ValueError("I/O operation on closed file."), None) # type: ignore[arg-type] - ) - - -def test_passes_through_other_unraisables() -> None: - assert not _is_urllib3_closed_file_noise( - _Args(ValueError("I/O operation on closed file."), object()) # type: ignore[arg-type] - ) - assert not _is_urllib3_closed_file_noise( - _Args(RuntimeError("boom"), _urllib3_response()) # type: ignore[arg-type] - ) - assert not _is_urllib3_closed_file_noise( - _Args(ValueError("something else"), _urllib3_response()) # type: ignore[arg-type] - ) - - -def test_installed_hook_filters_and_delegates(monkeypatch: pytest.MonkeyPatch) -> None: - calls: list[object] = [] - monkeypatch.setattr(sys, "unraisablehook", calls.append) - monkeypatch.setattr(tlog, "_unraisable_hook_installed", False) - tlog._silence_urllib3_finalizer_noise() - hook = sys.unraisablehook - assert hook is not calls.append - - hook(_Args(ValueError("I/O operation on closed file."), _urllib3_response())) # type: ignore[arg-type] - hook( - _Args( # type: ignore[arg-type] + _unraisable(ValueError("I/O operation on closed file."), object()), + _unraisable( ValueError("I/O operation on closed file."), None, err_msg=( "Exception ignored while finalizing file " "" ), - ) - ) - assert calls == [] + ), + _unraisable(RuntimeError("boom"), object()), + _unraisable(KeyError("x"), None, err_msg="Exception ignored in: "), + ], +) +def test_every_unraisable_is_logged_not_printed( + args: object, + hooks: tuple[list[object], list[object]], + strix_records: list[logging.LogRecord], + capsys: pytest.CaptureFixture[str], +) -> None: + unraisable_calls, _ = hooks - other = _Args(RuntimeError("boom"), object()) - hook(other) # type: ignore[arg-type] - assert calls == [other] + sys.unraisablehook(args) # type: ignore[arg-type] + + assert unraisable_calls == [] + assert capsys.readouterr().err == "" + [record] = strix_records + assert record.levelno == logging.WARNING + assert record.name == "strix.telemetry" + message = record.getMessage() + if args.err_msg: # type: ignore[attr-defined] + assert message.startswith(args.err_msg) # type: ignore[attr-defined] + else: + assert message.startswith("Exception ignored in None: + """After scan teardown the strix logger tree has no handlers; the report + must be dropped rather than handed to logging.lastResort (stderr).""" + root = logging.getLogger("strix") + saved, root.handlers = root.handlers, [] + try: + sys.unraisablehook(_unraisable(RuntimeError("late"), object())) # type: ignore[arg-type] + finally: + root.handlers = saved + assert capsys.readouterr().err == "" + + +def test_thread_exceptions_are_logged_not_printed( + hooks: tuple[list[object], list[object]], + strix_records: list[logging.LogRecord], + capsys: pytest.CaptureFixture[str], +) -> None: + _, thread_calls = hooks + + def _boom() -> None: + raise RuntimeError("worker failed") + + thread = threading.Thread(target=_boom, name="strix-worker") + thread.start() + thread.join() + + assert thread_calls == [] + assert capsys.readouterr().err == "" + [record] = strix_records + assert record.levelno == logging.WARNING + message = record.getMessage() + assert message.startswith("Exception in thread strix-worker") + assert "RuntimeError: worker failed" in message + + +@pytest.mark.usefixtures("hooks") +def test_thread_system_exit_is_ignored(strix_records: list[logging.LogRecord]) -> None: + thread = threading.Thread(target=sys.exit, args=(3,)) + thread.start() + thread.join() + assert strix_records == [] + + +def test_hooks_install_once(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(tlog, "_hooks_installed", False) + tlog.configure_dependency_logging() + installed = (sys.unraisablehook, threading.excepthook) + tlog.configure_dependency_logging() + assert (sys.unraisablehook, threading.excepthook) == installed + + +_EXIT_SCRIPT = r""" +import logging, sys, threading +from strix.telemetry.logging import setup_console_logging +setup_console_logging() + +class Leaky: + def __del__(self): + raise ValueError("I/O operation on closed file.") + +Leaky() # collected right away +keep = Leaky() # collected at interpreter shutdown + +def worker(): + raise RuntimeError("worker failed") +t = threading.Thread(target=worker); t.start(); t.join() + +import urllib3.response, io +resp = urllib3.response.HTTPResponse(body=io.BytesIO(b""), preload_content=False) +resp._fp.close() # socket file closed before the response: the 3.14 exit noise +del resp +print("done") +""" + + +def test_process_exit_prints_nothing_to_stderr() -> None: + """End to end in a fresh interpreter: finalizer errors (including one at + interpreter shutdown), a thread traceback and the closed-file response + case produce no stderr output, with the default (non-debug) handlers.""" + env = {"PYTHONPATH": str(Path(__file__).resolve().parents[1])} + proc = subprocess.run( # noqa: S603 + [sys.executable, "-c", _EXIT_SCRIPT], + capture_output=True, + text=True, + timeout=60, + env={**_safe_env(), **env, "STRIX_DEBUG": ""}, + check=False, + ) + assert proc.returncode == 0, proc.stderr + assert proc.stdout.strip() == "done" + assert proc.stderr == "" + + +def _safe_env() -> dict[str, str]: + return { + k: v for k, v in os.environ.items() if k in {"PATH", "HOME", "SYSTEMROOT", "TEMP", "TMP"} + }