Add backend logging

requirements.txt

@@ -6,6 +6,7 @@ fastapi==0.78.0
 gunicorn==20.1.0
 punq==0.6.2
 pydantic[email]==1.9.0
+python-json-logger==2.0.2
 uvicorn[standard]==0.17.6
 sqlalchemy[asyncio,mypy]==1.4.39
 

server/infrastructure/logging/config.py

@@ -0,0 +1,42 @@
+from server.config.settings import Settings
+
+
+def get_log_config(settings: Settings) -> dict:
+    return {
+        "version": 1,
+        "disable_existing_loggers": False,
+        "formatters": {
+            "console": {
+                "()": "uvicorn.logging.DefaultFormatter",
+                "format": "%(asctime)s %(levelprefix)-9s %(name)s: %(message)s",
+            },
+            "json": {
+                "()": "server.infrastructure.logging.formatters.JsonFormatter",
+                "format": "%(asctime)s %(levelname)s %(name)s %(message)s",
+            },
+        },
+        "handlers": {
+            "default": {
+                "level": "DEBUG",
+                "class": "logging.StreamHandler",
+                "formatter": "console" if settings.server_mode == "local" else "json",
+                "stream": "ext://sys.stdout",
+            },
+        },
+        "loggers": {
+            "": {
+                "handlers": ["default"],
+                "level": "DEBUG" if settings.debug else "INFO",
+            },
+            "uvicorn.error": {
+                "handlers": ["default"],
+                "level": "INFO",
+                "propagate": False,
+            },
+            "uvicorn.access": {
+                "handlers": ["default"],
+                "level": "INFO",
+                "propagate": False,
+            },
+        },
+    }

server/infrastructure/logging/formatters.py

@@ -0,0 +1,38 @@
+import http
+import logging
+from typing import Any
+
+from pythonjsonlogger import jsonlogger
+
+
+class JsonFormatter(jsonlogger.JsonFormatter):
+    def __init__(self, *args: Any, **kwargs: Any) -> None:
+        kwargs["reserved_attrs"] = [
+            # Drop Uvicorn's extras
+            # See: https://github.com/madzak/python-json-logger/issues/97
+            "color_message",
+            *jsonlogger.RESERVED_ATTRS,
+        ]
+        super().__init__(*args, **kwargs)
+
+
+class AccessJsonFormatter(JsonFormatter):
+    def add_fields(
+        self, log_record: dict, record: logging.LogRecord, message_dict: dict
+    ) -> None:
+        super().add_fields(log_record, record, message_dict)
+
+        # Comes from Uvicorn's access_logger.info(<message>, *args)
+        assert record.args
+
+        client_addr, method, full_path, http_version, status_code = record.args
+        assert isinstance(status_code, int)
+
+        try:
+            status_phrase = http.HTTPStatus(status_code).phrase
+        except ValueError:
+            status_phrase = ""
+
+        log_record["client_addr"] = client_addr
+        log_record["status"] = "%s %s" % (status_code, status_phrase)
+        log_record["request_line"] = "%s %s HTTP/%s" % (method, full_path, http_version)

server/infrastructure/server.py

@@ -0,0 +1,61 @@
+import uvicorn
+import uvicorn.supervisors
+
+from server.config.di import resolve
+from server.config.settings import Settings
+
+from .logging.config import get_log_config
+
+
+def get_server_config(app: str, settings: Settings = None) -> uvicorn.Config:
+    if settings is None:
+        settings = resolve(Settings)
+
+    kwargs = dict(
+        host=settings.host,
+        port=settings.port,
+        log_config=get_log_config(settings),
+    )
+
+    if settings.server_mode == "local":
+        kwargs.update(
+            # Enable hot reload.
+            reload=True,
+            reload_dirs=["server"],
+        )
+    elif settings.server_mode == "live":
+        kwargs.update(
+            # Pass any proxy headers, so that Uvicorn sees information about the
+            # connecting client, rather than the connecting Nginx proxy.
+            # See: https://www.uvicorn.org/deployment/#running-behind-nginx
+            proxy_headers=True,
+            # Match Nginx mount path.
+            root_path="/api",
+        )
+
+    return uvicorn.Config(app, **kwargs)
+
+
+def run(app: str) -> int:
+    """
+    Run the API server.
+
+    This is a simplified version of `uvicorn.run()`.
+    """
+    config = get_server_config(app)
+    server = uvicorn.Server(config=config)
+
+    if config.should_reload:
+        sock = config.bind_socket()
+        reloader = uvicorn.supervisors.ChangeReload(
+            config, target=server.run, sockets=[sock]
+        )
+        reloader.run()
+        return 0
+
+    server.run()
+
+    if not server.started:
+        return 3
+
+    return 0

server/main.py

@@ -1,37 +1,12 @@
+import sys
+
 from .api.app import create_app
 from .config.di import bootstrap
+from .infrastructure.server import run
 
 bootstrap()
 
 app = create_app()
 
 if __name__ == "__main__":
-    import uvicorn
-
-    from .config.di import resolve
-    from .config.settings import Settings
-
-    settings = resolve(Settings)
-
-    kwargs: dict = {
-        "host": settings.host,
-        "port": settings.port,
-    }
-
-    if settings.server_mode == "local":
-        kwargs.update(
-            # Enable hot reload.
-            reload=True,
-            reload_dirs=["server"],
-        )
-    elif settings.server_mode == "live":
-        kwargs.update(
-            # Pass any proxy headers, so that Uvicorn sees information about the
-            # connecting client, rather than the connecting Nginx proxy.
-            # See: https://www.uvicorn.org/deployment/#running-behind-nginx
-            proxy_headers=True,
-            # Match Nginx mount path.
-            root_path="/api",
-        )
-
-    uvicorn.run("server.main:app", **kwargs)
+    sys.exit(run("server.main:app"))

tests/infrastructure/test_logging.py

@@ -0,0 +1,71 @@
+import json
+import logging
+
+import pytest
+
+from server.config.di import configure
+from server.config.settings import Settings
+from server.infrastructure.server import get_server_config
+from server.seedwork.application.di import Container
+
+
+def test_logging(capsys: pytest.CaptureFixture) -> None:
+    config = get_server_config("server.main:app")
+    config.load()
+
+    logger = logging.getLogger("server.example")
+    logger.debug("Debug test")
+    logger.info("Info test")
+
+    captured = capsys.readouterr()
+    assert not captured.err
+    assert "Debug test" not in captured.out
+    assert "server.example: Info test" in captured.out
+
+
+def test_logging_debug(
+    monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture
+) -> None:
+    monkeypatch.setenv("APP_DEBUG", "1")
+
+    container = Container(configure)
+    container.bootstrap()
+
+    settings = container.resolve(Settings)
+    config = get_server_config("server.main:app", settings)
+    config.load()
+
+    logger = logging.getLogger("server.example")
+    logger.debug("Debug test")
+
+    captured = capsys.readouterr()
+    assert not captured.err
+    assert "server.example: Debug test" in captured.out
+
+
+def test_logging_live_renders_json(
+    monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture
+) -> None:
+    monkeypatch.setenv("APP_SERVER_MODE", "live")
+
+    container = Container(configure)
+    container.bootstrap()
+
+    settings = container.resolve(Settings)
+    config = get_server_config("server.main:app", settings)
+    config.load()
+
+    logger = logging.getLogger("server.example")
+    logger.info("Info test")
+
+    captured = capsys.readouterr()
+    assert not captured.err
+    info_line = json.loads(
+        next(line for line in captured.out.splitlines() if "Info test" in line)
+    )
+    assert info_line == {
+        "asctime": info_line["asctime"],
+        "levelname": "INFO",
+        "name": "server.example",
+        "message": "Info test",
+    }