diff --git a/apitally/client/base.py b/apitally/client/base.py index 677c804..26ec994 100644 --- a/apitally/client/base.py +++ b/apitally/client/base.py @@ -5,6 +5,7 @@ import re import threading import time +import traceback from abc import ABC from collections import Counter from dataclasses import dataclass @@ -24,6 +25,8 @@ SYNC_INTERVAL = 60 INITIAL_SYNC_INTERVAL = 10 INITIAL_SYNC_INTERVAL_DURATION = 3600 +MAX_EXCEPTION_MSG_LENGTH = 2048 +MAX_EXCEPTION_TRACEBACK_LENGTH = 65536 TApitallyClient = TypeVar("TApitallyClient", bound="ApitallyClientBase") @@ -54,6 +57,7 @@ def __init__(self, client_id: str, env: str) -> None: self.instance_uuid = str(uuid4()) self.request_counter = RequestCounter() self.validation_error_counter = ValidationErrorCounter() + self.server_error_counter = ServerErrorCounter() self._app_info_payload: Optional[Dict[str, Any]] = None self._app_info_sent = False @@ -86,11 +90,13 @@ def get_info_payload(self, app_info: Dict[str, Any]) -> Dict[str, Any]: def get_requests_payload(self) -> Dict[str, Any]: requests = self.request_counter.get_and_reset_requests() validation_errors = self.validation_error_counter.get_and_reset_validation_errors() + server_errors = self.server_error_counter.get_and_reset_server_errors() return { "instance_uuid": self.instance_uuid, "message_uuid": str(uuid4()), "requests": requests, "validation_errors": validation_errors, + "server_errors": server_errors, } @@ -222,3 +228,75 @@ def get_and_reset_validation_errors(self) -> List[Dict[str, Any]]: ) self.error_counts.clear() return data + + +@dataclass(frozen=True) +class ServerError: + consumer: Optional[str] + method: str + path: str + type: str + msg: str + traceback: str + + +class ServerErrorCounter: + def __init__(self) -> None: + self.error_counts: Counter[ServerError] = Counter() + self._lock = threading.Lock() + + def add_server_error(self, consumer: Optional[str], method: str, path: str, exception: BaseException) -> None: + if not isinstance(exception, BaseException): + return # pragma: no cover + exception_type = type(exception) + with self._lock: + server_error = ServerError( + consumer=consumer, + method=method.upper(), + path=path, + type=f"{exception_type.__module__}.{exception_type.__qualname__}", + msg=self._get_truncated_exception_msg(exception), + traceback=self._get_truncated_exception_traceback(exception), + ) + self.error_counts[server_error] += 1 + + def get_and_reset_server_errors(self) -> List[Dict[str, Any]]: + data: List[Dict[str, Any]] = [] + with self._lock: + for server_error, count in self.error_counts.items(): + data.append( + { + "consumer": server_error.consumer, + "method": server_error.method, + "path": server_error.path, + "type": server_error.type, + "msg": server_error.msg, + "traceback": server_error.traceback, + "error_count": count, + } + ) + self.error_counts.clear() + return data + + @staticmethod + def _get_truncated_exception_msg(exception: BaseException) -> str: + msg = str(exception).strip() + if len(msg) <= MAX_EXCEPTION_MSG_LENGTH: + return msg + suffix = "... (truncated)" + cutoff = MAX_EXCEPTION_MSG_LENGTH - len(suffix) + return msg[:cutoff] + suffix + + @staticmethod + def _get_truncated_exception_traceback(exception: BaseException) -> str: + prefix = "... (truncated) ...\n" + cutoff = MAX_EXCEPTION_TRACEBACK_LENGTH - len(prefix) + lines = [] + length = 0 + for line in traceback.format_exception(exception)[::-1]: + if length + len(line) > cutoff: + lines.append(prefix) + break + lines.append(line) + length += len(line) + return "".join(lines[::-1]).strip() diff --git a/apitally/django.py b/apitally/django.py index 500c15f..70a6999 100644 --- a/apitally/django.py +++ b/apitally/django.py @@ -126,8 +126,22 @@ def __call__(self, request: HttpRequest) -> HttpResponse: ) except Exception: # pragma: no cover logger.exception("Failed to log validation errors") + if response.status_code == 500 and hasattr(request, "unhandled_exception"): + try: + self.client.server_error_counter.add_server_error( + consumer=consumer, + method=request.method, + path=path, + exception=getattr(request, "unhandled_exception"), + ) + except Exception: # pragma: no cover + logger.exception("Failed to log server error") return response + def process_exception(self, request: HttpRequest, exception: Exception) -> None: + setattr(request, "unhandled_exception", exception) + return None + def get_path(self, request: HttpRequest) -> Optional[str]: if (match := request.resolver_match) is not None: try: diff --git a/apitally/flask.py b/apitally/flask.py index 7c353a7..59d6bfc 100644 --- a/apitally/flask.py +++ b/apitally/flask.py @@ -5,6 +5,7 @@ from typing import TYPE_CHECKING, Any, Dict, Iterable, List, Optional, Tuple from flask import Flask, g +from flask.wrappers import Response from werkzeug.datastructures import Headers from werkzeug.exceptions import NotFound from werkzeug.test import Client @@ -34,6 +35,7 @@ def __init__( self.app = app self.wsgi_app = app.wsgi_app self.filter_unhandled_paths = filter_unhandled_paths + self.patch_handle_exception() self.client = ApitallyClient(client_id=client_id, env=env) self.client.start_sync_loop() self.delayed_set_app_info(app_version, openapi_url) @@ -68,8 +70,21 @@ def catching_start_response(status: str, headers: List[Tuple[str, str]], exc_inf ) return response + def patch_handle_exception(self) -> None: + original_handle_exception = self.app.handle_exception + + def handle_exception(e: Exception) -> Response: + g.unhandled_exception = e + return original_handle_exception(e) + + self.app.handle_exception = handle_exception # type: ignore[method-assign] + def add_request( - self, environ: WSGIEnvironment, status_code: int, response_time: float, response_headers: Headers + self, + environ: WSGIEnvironment, + status_code: int, + response_time: float, + response_headers: Headers, ) -> None: rule, is_handled_path = self.get_rule(environ) if is_handled_path or not self.filter_unhandled_paths: @@ -82,6 +97,13 @@ def add_request( request_size=environ.get("CONTENT_LENGTH"), response_size=response_headers.get("Content-Length", type=int), ) + if status_code == 500 and "unhandled_exception" in g: + self.client.server_error_counter.add_server_error( + consumer=self.get_consumer(), + method=environ["REQUEST_METHOD"], + path=rule, + exception=g.unhandled_exception, + ) def get_rule(self, environ: WSGIEnvironment) -> Tuple[str, bool]: url_adapter = self.app.url_map.bind_to_environ(environ) diff --git a/apitally/litestar.py b/apitally/litestar.py index 4ece162..323779e 100644 --- a/apitally/litestar.py +++ b/apitally/litestar.py @@ -38,6 +38,7 @@ def on_app_init(self, app_config: AppConfig) -> AppConfig: app_config.on_startup.append(self.on_startup) app_config.on_shutdown.append(self.client.handle_shutdown) app_config.middleware.append(self.middleware_factory) + app_config.after_exception.append(self.after_exception) return app_config def on_startup(self, app: Litestar) -> None: @@ -58,6 +59,9 @@ def on_startup(self, app: Litestar) -> None: self.client.set_app_info(app_info) self.client.start_sync_loop() + def after_exception(self, exception: Exception, scope: Scope) -> None: + scope["state"]["exception"] = exception + def middleware_factory(self, app: ASGIApp) -> ASGIApp: async def middleware(scope: Scope, receive: Receive, send: Send) -> None: if scope["type"] == "http" and scope["method"] != "OPTIONS": @@ -139,6 +143,13 @@ def add_request( if "key" in error and "message" in error ], ) + if response_status == 500 and "exception" in request.state: + self.client.server_error_counter.add_server_error( + consumer=consumer, + method=request.method, + path=path, + exception=request.state["exception"], + ) def get_path(self, request: Request) -> Optional[str]: path: List[str] = [] diff --git a/apitally/starlette.py b/apitally/starlette.py index 24e1013..86ec0d9 100644 --- a/apitally/starlette.py +++ b/apitally/starlette.py @@ -64,6 +64,7 @@ async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) - response=None, status_code=HTTP_500_INTERNAL_SERVER_ERROR, response_time=time.perf_counter() - start_time, + exception=e, ) raise e from None else: @@ -76,7 +77,12 @@ async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) - return response async def add_request( - self, request: Request, response: Optional[Response], status_code: int, response_time: float + self, + request: Request, + response: Optional[Response], + status_code: int, + response_time: float, + exception: Optional[BaseException] = None, ) -> None: path_template, is_handled_path = self.get_path_template(request) if is_handled_path or not self.filter_unhandled_paths: @@ -104,6 +110,13 @@ async def add_request( path=path_template, detail=body["detail"], ) + if status_code == 500 and exception is not None: + self.client.server_error_counter.add_server_error( + consumer=consumer, + method=request.method, + path=path_template, + exception=exception, + ) @staticmethod async def get_response_json(response: Response) -> Any: diff --git a/tests/test_client_base.py b/tests/test_client_base.py index 970f1b7..e4021be 100644 --- a/tests/test_client_base.py +++ b/tests/test_client_base.py @@ -1,3 +1,6 @@ +from pytest_mock import MockerFixture + + def test_request_counter(): from apitally.client.base import RequestCounter @@ -93,3 +96,48 @@ def test_validation_error_counter(): assert data[0]["type"] == "type_error.integer" assert data[0]["msg"] == "value is not a valid integer" assert data[0]["error_count"] == 2 + + +def test_server_error_counter(): + from apitally.client.base import ServerErrorCounter + + server_errors = ServerErrorCounter() + server_errors.add_server_error( + consumer=None, + method="GET", + path="/test", + exception=ValueError("test"), + ) + server_errors.add_server_error( + consumer=None, + method="GET", + path="/test", + exception=ValueError("test"), + ) + + data = server_errors.get_and_reset_server_errors() + assert len(server_errors.error_counts) == 0 + assert len(data) == 1 + assert data[0]["method"] == "GET" + assert data[0]["path"] == "/test" + assert data[0]["type"] == "builtins.ValueError" + assert data[0]["msg"] == "test" + assert data[0]["error_count"] == 2 + + +def test_exception_truncation(mocker: MockerFixture): + from apitally.client.base import ServerErrorCounter + + mocker.patch("apitally.client.base.MAX_EXCEPTION_MSG_LENGTH", 32) + mocker.patch("apitally.client.base.MAX_EXCEPTION_TRACEBACK_LENGTH", 128) + + try: + raise ValueError("a" * 88) + except ValueError as e: + msg = ServerErrorCounter._get_truncated_exception_msg(e) + tb = ServerErrorCounter._get_truncated_exception_traceback(e) + + assert len(msg) == 32 + assert msg.endswith("... (truncated)") + assert len(tb) <= 128 + assert tb.startswith("... (truncated) ...\n") diff --git a/tests/test_django_ninja.py b/tests/test_django_ninja.py index d47adfd..746f8a8 100644 --- a/tests/test_django_ninja.py +++ b/tests/test_django_ninja.py @@ -97,16 +97,22 @@ def test_middleware_requests_404(client: Client, mocker: MockerFixture): def test_middleware_requests_error(client: Client, mocker: MockerFixture): - mock = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock1 = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock2 = mocker.patch("apitally.client.base.ServerErrorCounter.add_server_error") response = client.put("/api/baz") assert response.status_code == 500 - mock.assert_called_once() - assert mock.call_args is not None - assert mock.call_args.kwargs["method"] == "PUT" - assert mock.call_args.kwargs["path"] == "/api/baz" - assert mock.call_args.kwargs["status_code"] == 500 - assert mock.call_args.kwargs["response_time"] > 0 + mock1.assert_called_once() + assert mock1.call_args is not None + assert mock1.call_args.kwargs["method"] == "PUT" + assert mock1.call_args.kwargs["path"] == "/api/baz" + assert mock1.call_args.kwargs["status_code"] == 500 + assert mock1.call_args.kwargs["response_time"] > 0 + + mock2.assert_called_once() + assert mock2.call_args is not None + exception = mock2.call_args.kwargs["exception"] + assert isinstance(exception, ValueError) def test_middleware_validation_error(client: Client, mocker: MockerFixture): diff --git a/tests/test_django_rest_framework.py b/tests/test_django_rest_framework.py index c411f05..523316b 100644 --- a/tests/test_django_rest_framework.py +++ b/tests/test_django_rest_framework.py @@ -95,16 +95,22 @@ def test_middleware_requests_404(client: APIClient, mocker: MockerFixture): def test_middleware_requests_error(client: APIClient, mocker: MockerFixture): - mock = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock1 = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock2 = mocker.patch("apitally.client.base.ServerErrorCounter.add_server_error") response = client.put("/baz/") assert response.status_code == 500 - mock.assert_called_once() - assert mock.call_args is not None - assert mock.call_args.kwargs["method"] == "PUT" - assert mock.call_args.kwargs["path"] == "/baz/" - assert mock.call_args.kwargs["status_code"] == 500 - assert mock.call_args.kwargs["response_time"] > 0 + mock1.assert_called_once() + assert mock1.call_args is not None + assert mock1.call_args.kwargs["method"] == "PUT" + assert mock1.call_args.kwargs["path"] == "/baz/" + assert mock1.call_args.kwargs["status_code"] == 500 + assert mock1.call_args.kwargs["response_time"] > 0 + + mock2.assert_called_once() + assert mock2.call_args is not None + exception = mock2.call_args.kwargs["exception"] + assert isinstance(exception, ValueError) def test_get_app_info(): diff --git a/tests/test_flask.py b/tests/test_flask.py index 83e988f..2b80a1c 100644 --- a/tests/test_flask.py +++ b/tests/test_flask.py @@ -67,17 +67,23 @@ def test_middleware_requests_ok(app: Flask, mocker: MockerFixture): def test_middleware_requests_error(app: Flask, mocker: MockerFixture): - mock = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock1 = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock2 = mocker.patch("apitally.client.base.ServerErrorCounter.add_server_error") client = app.test_client() response = client.put("/baz") assert response.status_code == 500 - mock.assert_called_once() - assert mock.call_args is not None - assert mock.call_args.kwargs["method"] == "PUT" - assert mock.call_args.kwargs["path"] == "/baz" - assert mock.call_args.kwargs["status_code"] == 500 - assert mock.call_args.kwargs["response_time"] > 0 + mock1.assert_called_once() + assert mock1.call_args is not None + assert mock1.call_args.kwargs["method"] == "PUT" + assert mock1.call_args.kwargs["path"] == "/baz" + assert mock1.call_args.kwargs["status_code"] == 500 + assert mock1.call_args.kwargs["response_time"] > 0 + + mock2.assert_called_once() + assert mock2.call_args is not None + exception = mock2.call_args.kwargs["exception"] + assert isinstance(exception, ValueError) def test_middleware_requests_unhandled(app: Flask, mocker: MockerFixture): diff --git a/tests/test_litestar.py b/tests/test_litestar.py index fbfe195..b274340 100644 --- a/tests/test_litestar.py +++ b/tests/test_litestar.py @@ -114,16 +114,22 @@ def test_middleware_requests_unhandled(client: TestClient, mocker: MockerFixture def test_middleware_requests_error(client: TestClient, mocker: MockerFixture): - mock = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock1 = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock2 = mocker.patch("apitally.client.base.ServerErrorCounter.add_server_error") response = client.post("/baz") assert response.status_code == 500 - mock.assert_called_once() - assert mock.call_args is not None - assert mock.call_args.kwargs["method"] == "POST" - assert mock.call_args.kwargs["path"] == "/baz" - assert mock.call_args.kwargs["status_code"] == 500 - assert mock.call_args.kwargs["response_time"] > 0 + mock1.assert_called_once() + assert mock1.call_args is not None + assert mock1.call_args.kwargs["method"] == "POST" + assert mock1.call_args.kwargs["path"] == "/baz" + assert mock1.call_args.kwargs["status_code"] == 500 + assert mock1.call_args.kwargs["response_time"] > 0 + + mock2.assert_called_once() + assert mock2.call_args is not None + exception = mock2.call_args.kwargs["exception"] + assert isinstance(exception, ValueError) def test_middleware_validation_error(client: TestClient, mocker: MockerFixture): diff --git a/tests/test_starlette.py b/tests/test_starlette.py index 7a174af..806509a 100644 --- a/tests/test_starlette.py +++ b/tests/test_starlette.py @@ -130,17 +130,23 @@ def test_middleware_requests_ok(app: Starlette, mocker: MockerFixture): def test_middleware_requests_error(app: Starlette, mocker: MockerFixture): from starlette.testclient import TestClient - mock = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock1 = mocker.patch("apitally.client.base.RequestCounter.add_request") + mock2 = mocker.patch("apitally.client.base.ServerErrorCounter.add_server_error") client = TestClient(app, raise_server_exceptions=False) response = client.post("/baz/") assert response.status_code == 500 - mock.assert_called_once() - assert mock.call_args is not None - assert mock.call_args.kwargs["method"] == "POST" - assert mock.call_args.kwargs["path"] == "/baz/" - assert mock.call_args.kwargs["status_code"] == 500 - assert mock.call_args.kwargs["response_time"] > 0 + mock1.assert_called_once() + assert mock1.call_args is not None + assert mock1.call_args.kwargs["method"] == "POST" + assert mock1.call_args.kwargs["path"] == "/baz/" + assert mock1.call_args.kwargs["status_code"] == 500 + assert mock1.call_args.kwargs["response_time"] > 0 + + mock2.assert_called_once() + assert mock2.call_args is not None + exception = mock2.call_args.kwargs["exception"] + assert isinstance(exception, ValueError) def test_middleware_requests_unhandled(app: Starlette, mocker: MockerFixture):