From d675c0dc2666be4f3c006e0b96f7d1891572a777 Mon Sep 17 00:00:00 2001 From: Kevin Morris Date: Sun, 9 Jan 2022 22:32:49 -0800 Subject: [PATCH] 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 ''` - If `options.traceback` is set to `1`, traceback is displayed in the new 500.html template. Signed-off-by: Kevin Morris --- aurweb/asgi.py | 65 ++++++++++++++++++++++++++++++++++++++- aurweb/models/user.py | 9 ++---- aurweb/scripts/notify.py | 55 +++++++++++++++++++++++++++++++-- conf/config.defaults | 5 +++ conf/config.dev | 1 + po/aurweb.pot | 17 ++++++++++ templates/errors/500.html | 20 ++++++++++++ test/test_asgi.py | 51 ++++++++++++++++++++++++++++++ test/test_auth_routes.py | 12 ++++++-- web/html/css/aurweb.css | 9 ++++++ 10 files changed, 230 insertions(+), 14 deletions(-) create mode 100644 templates/errors/500.html diff --git a/aurweb/asgi.py b/aurweb/asgi.py index cbb84f8a..95bd5e77 100644 --- a/aurweb/asgi.py +++ b/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 """ - response = await util.error_or_result(call_next, request) + 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 diff --git a/aurweb/models/user.py b/aurweb/models/user.py index fe342eac..fcf4a9b3 100644 --- a/aurweb/models/user.py +++ b/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 " - f"{tries} iterations.") - logger.error(str(exc)) - raise HTTPException(status_code=HTTPStatus.INTERNAL_SERVER_ERROR, - detail=detail) + raise exc return self.session.SessionID diff --git a/aurweb/scripts/notify.py b/aurweb/scripts/notify.py index 20e8a5d5..1f875a9c 100755 --- a/aurweb/scripts/notify.py +++ b/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.models import (PackageBase, PackageComaintainer, PackageComment, PackageNotification, PackageRequest, RequestType, - TUVote, User) +from aurweb import db, l10n, logging +from aurweb.models import PackageBase, 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): diff --git a/conf/config.defaults b/conf/config.defaults index 082d51a5..cb96bad2 100644 --- a/conf/config.defaults +++ b/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 diff --git a/conf/config.dev b/conf/config.dev index e97f6f12..923c34ff 100644 --- a/conf/config.dev +++ b/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 diff --git a/po/aurweb.pot b/po/aurweb.pot index f6d1377b..adc1fc3a 100644 --- a/po/aurweb.pot +++ b/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 "" diff --git a/templates/errors/500.html b/templates/errors/500.html new file mode 100644 index 00000000..1a9bfa6b --- /dev/null +++ b/templates/errors/500.html @@ -0,0 +1,20 @@ +{% extends "partials/layout.html" %} + +{% block pageContent %} +
+

500 - {{ "Internal Server Error" | tr }}

+ +

+ {{ "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 + }} +

+ + {% if config.getboolean("options", "traceback") %} + 
{{ traceback }}
+ {% endif %} +
+{% endblock %} diff --git a/test/test_asgi.py b/test/test_asgi.py index 16b07c31..af13266f 100644 --- a/test/test_asgi.py +++ b/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 diff --git a/test/test_auth_routes.py b/test/test_auth_routes.py index f3e2a011..be24d582 100644 --- a/test/test_auth_routes.py +++ b/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) diff --git a/web/html/css/aurweb.css b/web/html/css/aurweb.css index 739ac7b7..ac20aac5 100644 --- a/web/html/css/aurweb.css +++ b/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; +}