Capture exception info for server errors (#19)

* WIP

* WIP

* Add separate type field

* Add no cover comment

* Truncate exception msg and traceback

Author: itssimon

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()

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:

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)

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] = []

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:

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")

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):

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():