mirror of
https://github.com/usestrix/strix.git
synced 2026-10-05 02:41:38 +00:00
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.
This commit is contained in:
Ahmed Allam
Ahmed Allam
parent
121216096c
commit
fa5f99c4e0
2 changed files with 239 additions and 119 deletions
|
|
@ -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]
|
||||
|
|
|
|||
|
|
@ -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",
|
||||
[
|
||||
"<urllib3.response.HTTPResponse object at 0x7f2d3c1f0b10>",
|
||||
"<http.client.HTTPResponse object at 0x7f2d3c1f0b10>",
|
||||
],
|
||||
)
|
||||
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 "
|
||||
"<urllib3.response.HTTPResponse object at 0x1>"
|
||||
),
|
||||
)
|
||||
)
|
||||
assert calls == []
|
||||
),
|
||||
_unraisable(RuntimeError("boom"), object()),
|
||||
_unraisable(KeyError("x"), None, err_msg="Exception ignored in: <function f>"),
|
||||
],
|
||||
)
|
||||
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 <object object")
|
||||
assert str(args.exc_value) in message # type: ignore[attr-defined]
|
||||
|
||||
|
||||
@pytest.mark.usefixtures("hooks")
|
||||
def test_unraisable_is_dropped_when_strix_has_no_handlers(
|
||||
capsys: pytest.CaptureFixture[str],
|
||||
) -> 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"}
|
||||
}
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue