feat(python): catch all exceptions thrown through fastapi route paths

This commit does quite a bit:
- Catches unhandled exceptions raised in the route handler and
  produces a 500 Internal Server Error Arch-themed response.
- Each unhandled exception causes a notification to be sent to new
  `notifications.postmaster` email with a "Traceback ID."
- Traceback ID is logged to the server along with the traceback which
  caused the 500: `docker-compose logs fastapi | grep '<traceback_id>'`
- If `options.traceback` is set to `1`, traceback is displayed in
  the new 500.html template.

Signed-off-by: Kevin Morris <kevr@0cost.org>

aurweb/asgi.py

@@ -1,7 +1,10 @@
+import hashlib
 import http
+import io
 import os
 import re
 import sys
+import traceback
 import typing
 
 from urllib.parse import quote_plus
@@ -26,7 +29,9 @@ from aurweb.db import get_engine, query
 from aurweb.models import AcceptedTerm, Term
 from aurweb.packages.util import get_pkg_or_base
 from aurweb.prometheus import instrumentator
+from aurweb.redis import redis_connection
 from aurweb.routers import APP_ROUTES
+from aurweb.scripts import notify
 from aurweb.templates import make_context, render_template
 
 logger = logging.get_logger(__name__)
@@ -95,6 +100,61 @@ def child_exit(server, worker):  # pragma: no cover
     multiprocess.mark_process_dead(worker.pid)
 
 
+async def internal_server_error(request: Request, exc: Exception) -> Response:
+    """
+    Catch all uncaught Exceptions thrown in a route.
+
+    :param request: FastAPI Request
+    :return: Rendered 500.html template with status_code 500
+    """
+    context = make_context(request, "Internal Server Error")
+
+    # Print out the exception via `traceback` and store the value
+    # into the `traceback` context variable.
+    tb_io = io.StringIO()
+    traceback.print_exc(file=tb_io)
+    tb = tb_io.getvalue()
+    context["traceback"] = tb
+
+    # Produce a SHA1 hash of the traceback string.
+    tb_hash = hashlib.sha1(tb.encode()).hexdigest()
+
+    # Use the first 7 characters of the sha1 for the traceback id.
+    # We will use this to log and include in the notification.
+    tb_id = tb_hash[:7]
+
+    redis = redis_connection()
+    pipe = redis.pipeline()
+    key = f"tb:{tb_hash}"
+    pipe.get(key)
+    retval, = pipe.execute()
+    if not retval:
+        # Expire in one hour; this is just done to make sure we
+        # don't infinitely store these values, but reduce the number
+        # of automated reports (notification below). At this time of
+        # writing, unexpected exceptions are not common, thus this
+        # will not produce a large memory footprint in redis.
+        pipe.set(key, tb)
+        pipe.expire(key, 3600)
+        pipe.execute()
+
+        # Send out notification about it.
+        notif = notify.ServerErrorNotification(
+            tb_id, context.get("version"), context.get("utcnow"))
+        notif.send()
+
+        retval = tb
+    else:
+        retval = retval.decode()
+
+    # Log details about the exception traceback.
+    logger.error(f"FATAL[{tb_id}]: An unexpected exception has occurred.")
+    logger.error(retval)
+
+    return render_template(request, "errors/500.html", context,
+                           status_code=http.HTTPStatus.INTERNAL_SERVER_ERROR)
+
+
 @app.exception_handler(StarletteHTTPException)
 async def http_exception_handler(request: Request, exc: HTTPException) \
         -> Response:
@@ -133,7 +193,10 @@ async def add_security_headers(request: Request, call_next: typing.Callable):
     RP: Referrer-Policy
     XFO: X-Frame-Options
     """
+    try:
         response = await util.error_or_result(call_next, request)
+    except Exception as exc:
+        return await internal_server_error(request, exc)
 
     # Add CSP header.
     nonce = request.user.nonce

aurweb/models/user.py

@@ -1,12 +1,11 @@
 import hashlib
 
 from datetime import datetime
-from http import HTTPStatus
 from typing import List, Set
 
 import bcrypt
 
-from fastapi import HTTPException, Request
+from fastapi import Request
 from sqlalchemy import or_
 from sqlalchemy.exc import IntegrityError
 from sqlalchemy.orm import backref, relationship
@@ -142,11 +141,7 @@ class User(Base):
                 exc = exc_
 
         if exc:
-            detail = ("Unable to generate a unique session ID in "
+            raise exc
-                      f"{tries} iterations.")
-            logger.error(str(exc))
-            raise HTTPException(status_code=HTTPStatus.INTERNAL_SERVER_ERROR,
-                                detail=detail)
 
         return self.session.SessionID
 

aurweb/scripts/notify.py

@@ -7,15 +7,22 @@ import subprocess
 import sys
 import textwrap
 
+from typing import List, Tuple
+
 from sqlalchemy import and_, or_
 
 import aurweb.config
 import aurweb.db
 import aurweb.l10n
 
-from aurweb import db, logging
+from aurweb import db, l10n, logging
-from aurweb.models import (PackageBase, PackageComaintainer, PackageComment, PackageNotification, PackageRequest, RequestType,
+from aurweb.models import PackageBase, User
-                           TUVote, User)
+from aurweb.models.package_comaintainer import PackageComaintainer
+from aurweb.models.package_comment import PackageComment
+from aurweb.models.package_notification import PackageNotification
+from aurweb.models.package_request import PackageRequest
+from aurweb.models.request_type import RequestType
+from aurweb.models.tu_vote import TUVote
 
 logger = logging.get_logger(__name__)
 
@@ -122,6 +129,48 @@ class Notification:
             logger.error(str(exc))
 
 
+class ServerErrorNotification(Notification):
+    """ A notification used to represent an internal server error. """
+
+    def __init__(self, traceback_id: int, version: str, utc: int):
+        """
+        Construct a ServerErrorNotification.
+
+        :param traceback_id: Traceback ID
+        :param version: aurweb version
+        :param utc: UTC timestamp
+        """
+        self._tb_id = traceback_id
+        self._version = version
+        self._utc = utc
+
+        postmaster = aurweb.config.get("notifications", "postmaster")
+        self._to = postmaster
+
+        super().__init__()
+
+    def get_recipients(self) -> List[Tuple[str, str]]:
+        from aurweb.auth import AnonymousUser
+        user = (db.query(User).filter(User.Email == self._to).first()
+                or AnonymousUser())
+        return [(self._to, user.LangPreference)]
+
+    def get_subject(self, lang: str) -> str:
+        return l10n.translator.translate("AUR Server Error", lang)
+
+    def get_body(self, lang: str) -> str:
+        """ A forcibly English email body. """
+        dt = aurweb.util.timestamp_to_datetime(self._utc)
+        dts = dt.strftime("%Y-%m-%d %H:%M")
+        return (f"Traceback ID: {self._tb_id}\n"
+                f"Location: {aur_location}\n"
+                f"Version: {self._version}\n"
+                f"Datetime: {dts} UTC\n")
+
+    def get_refs(self):
+        return (aur_location,)
+
+
 class ResetKeyNotification(Notification):
     def __init__(self, uid):
 

conf/config.defaults

@@ -44,6 +44,8 @@ cache_pkginfo_ttl = 86400
 memcache_servers = 127.0.0.1:11211
 salt_rounds = 12
 redis_address = redis://localhost
+; Toggles traceback display in templates/errors/500.html.
+traceback = 0
 
 [ratelimit]
 request_limit = 4000
@@ -65,6 +67,9 @@ smtp-user =
 smtp-password =
 sender = notify@aur.archlinux.org
 reply-to = noreply@aur.archlinux.org
+; Administration email which will receive notifications about
+; various server details like uncaught exceptions.
+postmaster = admin@example.org
 
 [fingerprints]
 Ed25519 = SHA256:HQ03dn6EasJHNDlt51KpQpFkT3yBX83x7BoIkA1iv2k

conf/config.dev

@@ -37,6 +37,7 @@ memcache_servers = memcached:11211
 ; If cache = 'redis' this address is used to connect to Redis.
 redis_address = redis://127.0.0.1
 aur_request_ml = aur-requests@localhost
+traceback = 1
 
 [notifications]
 ; For development/testing, use /usr/bin/sendmail

po/aurweb.pot

@@ -2304,3 +2304,20 @@ msgstr ""
 #: aurweb/packages/requests.py
 msgid "No due existing orphan requests to accept for %s."
 msgstr ""
+
+#: aurweb/asgi.py
+msgid "Internal Server Error"
+msgstr ""
+
+#: templates/errors/500.html
+msgid "A fatal error has occurred."
+msgstr ""
+
+#: templates/errors/500.html
+msgid "Details have been logged and will be reviewed by the postmaster "
+"posthaste. We apologize for any inconvenience this may have caused."
+msgstr ""
+
+#: aurweb/scripts/notify.py
+msgid "AUR Server Error"
+msgstr ""

templates/errors/500.html

@@ -0,0 +1,20 @@
+{% extends "partials/layout.html" %}
+
+{% block pageContent %}
+    <div class="box">
+        <h2>500 - {{ "Internal Server Error" | tr }}</h2>
+
+        <p>
+            {{ "A fatal error has occurred." | tr }}
+            {{
+                "Details have been logged and will be reviewed by the "
+                "postmaster posthaste. We apologize for any inconvenience "
+                "this may have caused." | tr
+            }}
+        </p>
+
+        {% if config.getboolean("options", "traceback") %}
+            <pre class="traceback">{{ traceback }}</pre>
+        {% endif %}
+    </div>
+{% endblock %}

test/test_asgi.py

@@ -1,19 +1,28 @@
 import http
 import os
+import re
 
 from unittest import mock
 
+import fastapi
 import pytest
 
 from fastapi import HTTPException
+from fastapi.testclient import TestClient
 
 import aurweb.asgi
 import aurweb.config
 import aurweb.redis
 
+from aurweb.testing.email import Email
 from aurweb.testing.requests import Request
 
 
+@pytest.fixture
+def setup(db_test, email_test):
+    return
+
+
 @pytest.mark.asyncio
 async def test_asgi_startup_session_secret_exception(monkeypatch):
     """ Test that we get an IOError on app_startup when we cannot
@@ -66,3 +75,45 @@ async def test_asgi_app_unsupported_backends():
         expr = r"^.*\(sqlite\) is unsupported.*$"
         with pytest.raises(ValueError, match=expr):
             await aurweb.asgi.app_startup()
+
+
+def test_internal_server_error(setup: None,
+                               caplog: pytest.LogCaptureFixture):
+    config_getboolean = aurweb.config.getboolean
+
+    def mock_getboolean(section: str, key: str) -> bool:
+        if section == "options" and key == "traceback":
+            return True
+        return config_getboolean(section, key)
+
+    @aurweb.asgi.app.get("/internal_server_error")
+    async def internal_server_error(request: fastapi.Request):
+        raise ValueError("test exception")
+
+    with mock.patch("aurweb.config.getboolean", side_effect=mock_getboolean):
+        with TestClient(app=aurweb.asgi.app) as request:
+            resp = request.get("/internal_server_error")
+    assert resp.status_code == int(http.HTTPStatus.INTERNAL_SERVER_ERROR)
+
+    # Let's assert that a notification was sent out to the postmaster.
+    assert Email.count() == 1
+
+    aur_location = aurweb.config.get("options", "aur_location")
+    email = Email(1)
+    assert f"Location: {aur_location}" in email.body
+    assert "Traceback ID:" in email.body
+    assert "Version:" in email.body
+    assert "Datetime:" in email.body
+    assert f"[1] {aur_location}" in email.body
+
+    # Assert that the exception got logged with with its traceback id.
+    expr = r"FATAL\[.{7}\]"
+    assert re.search(expr, caplog.text)
+
+    # Let's do it again; no email should be sent the next time,
+    # since the hash is stored in redis.
+    with mock.patch("aurweb.config.getboolean", side_effect=mock_getboolean):
+        with TestClient(app=aurweb.asgi.app) as request:
+            resp = request.get("/internal_server_error")
+    assert resp.status_code == int(http.HTTPStatus.INTERNAL_SERVER_ERROR)
+    assert Email.count() == 1

test/test_auth_routes.py

@@ -1,3 +1,5 @@
+import re
+
 from datetime import datetime
 from http import HTTPStatus
 from unittest import mock
@@ -322,9 +324,13 @@ def test_generate_unique_sid_exhausted(client: TestClient, user: User,
             response = request.post("/login", data=post_data, cookies={})
     assert response.status_code == int(HTTPStatus.INTERNAL_SERVER_ERROR)
 
-    expected = "Unable to generate a unique session ID"
-    assert expected in response.text
     assert "500 - Internal Server Error" in response.text
 
-    # Make sure an IntegrityError from the DB got logged out.
+    # Make sure an IntegrityError from the DB got logged out
+    # with a FATAL traceback ID.
+    expr = r"FATAL\[.{7}\]"
+    assert re.search(expr, caplog.text)
     assert "IntegrityError" in caplog.text
+
+    expr = r"Duplicate entry .+ for key .+SessionID.+"
+    assert re.search(expr, response.text)

web/html/css/aurweb.css

@@ -255,3 +255,12 @@ div.box form.link p {
 div.box form.link button {
     padding: 0;
 }
+
+pre.traceback {
+    /* https://css-tricks.com/snippets/css/make-pre-text-wrap/ */
+    white-space: pre-wrap;
+    white-space: -moz-pre-wrap;
+    white-space: -pre-wrap;
+    white-space: -o-pre-wrap;
+    word-wrap: break-all;
+}