Add backend logging configuration (#304)

* Add backend logging

* Format

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

@@ -6,6 +6,8 @@
 from server.config.di import resolve
 from server.config.settings import Settings
 
+from .logging.config import get_log_config
+
 
 def get_server_config(
     app: Union[str, Callable], settings: Settings = None
@@ -16,6 +18,7 @@ def get_server_config(
     kwargs = dict(
         host=settings.host,
         port=settings.port,
+        log_config=get_log_config(settings),
     )
 
     if settings.server_mode == "local":

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