From 605a7f2a2aeeb09ad120b237f055273c9cf6d230 Mon Sep 17 00:00:00 2001 From: Florimond Manca Date: Thu, 30 Jun 2022 12:49:07 +0200 Subject: [PATCH] Add backend logging configuration (#304) * Add backend logging * Format --- requirements.txt | 1 + server/infrastructure/logging/__init__.py | 0 server/infrastructure/logging/config.py | 42 +++++++++++ server/infrastructure/logging/formatters.py | 38 ++++++++++ server/infrastructure/server.py | 3 + .../{test_config.py => test_server_config.py} | 0 tests/infrastructure/test_logging.py | 71 +++++++++++++++++++ 7 files changed, 155 insertions(+) create mode 100644 server/infrastructure/logging/__init__.py create mode 100644 server/infrastructure/logging/config.py create mode 100644 server/infrastructure/logging/formatters.py rename tests/api/{test_config.py => test_server_config.py} (100%) create mode 100644 tests/infrastructure/test_logging.py diff --git a/requirements.txt b/requirements.txt index 97aa7448..da9f588c 100644 --- a/requirements.txt +++ b/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 diff --git a/server/infrastructure/logging/__init__.py b/server/infrastructure/logging/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/server/infrastructure/logging/config.py b/server/infrastructure/logging/config.py new file mode 100644 index 00000000..db65029c --- /dev/null +++ b/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, + }, + }, + } diff --git a/server/infrastructure/logging/formatters.py b/server/infrastructure/logging/formatters.py new file mode 100644 index 00000000..3bc29d9a --- /dev/null +++ b/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(, *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) diff --git a/server/infrastructure/server.py b/server/infrastructure/server.py index cfbfa3d0..579601e2 100644 --- a/server/infrastructure/server.py +++ b/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": diff --git a/tests/api/test_config.py b/tests/api/test_server_config.py similarity index 100% rename from tests/api/test_config.py rename to tests/api/test_server_config.py diff --git a/tests/infrastructure/test_logging.py b/tests/infrastructure/test_logging.py new file mode 100644 index 00000000..cf6a63e1 --- /dev/null +++ b/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", + }