Add logging configuration and setup (#306)

Related to #182.

Adds logging configuration and setup.

 - By default log everything to `develop.log`
 - Additional log sinks can be defined in `config.toml`
- Every request is automatically assigned a request identifier, which is
automatically included in every log call in that request.
 - The request and response is (partially) logged with every request

The exact interaction for logging response and request content needs to
be examined (which should be logged, make use of background tasks, ...).

---------

Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>

Author: PGijsbers

.gitignore

@@ -1,4 +1,6 @@
 docker/mysql/data
+*.log
+logs/
 .DS_Store
 
 # Byte-compiled / optimized / DLL files

pyproject.toml

@@ -14,6 +14,7 @@ classifiers = [
 ]
 dependencies = [
     "fastapi",
+    "loguru",
     "cryptography",
     "pydantic",
     "uvicorn",

src/config.py

@@ -1,13 +1,11 @@
 import functools
-import logging
 import os
 import tomllib
 import typing
 from pathlib import Path
 
 from dotenv import load_dotenv
-
-logger = logging.getLogger(__name__)
+from loguru import logger
 
 TomlTable = dict[str, typing.Any]
 
@@ -27,9 +25,13 @@
 _dotenv_file = Path(os.getenv(DOTENV_FILE_ENV, _config_directory / ".env"))
 _dotenv_file = _dotenv_file.expanduser().absolute()
 
-logger.info("Configuration directory is '%s'", _config_directory)
-logger.info("Loading configuration file from '%s'", _config_file)
-logger.info("Loading environment variables from '%s'", _dotenv_file)
+
+logger.info(
+    "Determined configuration sources.",
+    configuration_directory=_config_directory,
+    configuration_file=_config_file,
+    dotenv_file=_dotenv_file,
+)
 
 load_dotenv(dotenv_path=_dotenv_file)
 
@@ -77,5 +79,6 @@ def load_database_configuration(file: Path = _config_file) -> TomlTable:
     return database_configuration
 
 
-def load_configuration(file: Path = _config_file) -> TomlTable:
+def load_configuration(file: Path | None = None) -> TomlTable:
+    file = file or _config_file
     return tomllib.loads(file.read_text())

src/config.toml

@@ -4,6 +4,21 @@ minio_base_url="https://openml1.win.tue.nl"
 [development]
 allow_test_api_keys=true
 
+# Any number of logging.NAME configurations can be added.
+# NAME is for reference only, it has no meaning otherwise.
+# You can add any arguments to `loguru.logger.add`,
+# the `sink` variable will be used as first positional argument.
+# https://loguru.readthedocs.io/en/stable/api/logger.html
+[logging.develop]
+sink="develop.log"
+# One of loguru levels: TRACE, DEBUG, INFO, SUCCESS, WARNING, ERROR
+level="DEBUG"
+# Automatically create a new file by date or file size
+rotation="50 MB"
+# Retention specifies the timespan after which automatic cleanup occurs.
+retention="1 day"
+compression="gz"
+
 [fastapi]
 root_path=""
 

src/core/logging.py

@@ -0,0 +1,56 @@
+"""Utility functions for logging."""
+
+import sys
+import uuid
+from collections.abc import Awaitable, Callable
+from pathlib import Path
+
+from loguru import logger
+from starlette.requests import Request
+from starlette.responses import Response
+
+from config import load_configuration
+
+
+def setup_log_sinks(configuration_file: Path | None = None) -> None:
+    """Configure loguru based on app configuration."""
+    configuration = load_configuration(configuration_file)
+    for nickname, sink_configuration in configuration.get("logging", {}).items():
+        logger.info("Configuring sink", nickname=nickname, **sink_configuration)
+        sink = sink_configuration.pop("sink")
+        if sink == "sys.stderr":
+            sink = sys.stderr
+        logger.add(sink, serialize=True, **sink_configuration)
+
+
+async def add_request_context_to_log(
+    request: Request,
+    call_next: Callable[[Request], Awaitable[Response]],
+) -> Response:
+    """Add a unique request id to each log call."""
+    identifier = uuid.uuid4().hex
+    with logger.contextualize(request_id=identifier):
+        return await call_next(request)
+
+
+async def request_response_logger(
+    request: Request,
+    call_next: Callable[[Request], Awaitable[Response]],
+) -> Response:
+    """Log the incoming request and outgoing response."""
+    logger.info(
+        "request",
+        url=request.url,
+        headers=request.headers,
+        cookies=request.cookies,
+        path_params=request.path_params,
+        query_params=request.query_params,
+    )
+    response: Response = await call_next(request)
+    logger.info(
+        "response",
+        status_code=response.status_code,
+        headers=response.headers,
+        media_type=response.media_type,
+    )
+    return response

src/main.py

@@ -1,13 +1,16 @@
 import argparse
-import logging
+import sys
 from collections.abc import AsyncGenerator
 from contextlib import asynccontextmanager
+from pathlib import Path
 
 import uvicorn
 from fastapi import FastAPI
+from loguru import logger
 
 from config import load_configuration
 from core.errors import ProblemDetailError, problem_detail_exception_handler
+from core.logging import add_request_context_to_log, request_response_logger, setup_log_sinks
 from database.setup import close_databases
 from routers.mldcat_ap.dataset import router as mldcat_ap_router
 from routers.openml.datasets import router as datasets_router
@@ -55,12 +58,25 @@ def _parse_args() -> argparse.Namespace:
     return parser.parse_args()
 
 
-def create_api() -> FastAPI:
-    fastapi_kwargs = load_configuration()["fastapi"]
+def create_api(configuration_file: Path | None = None) -> FastAPI:
+    # Default logging configuration so we have logs during setup
+    logger.remove()
+    setup_sink = logger.add(sys.stderr, serialize=True)
+    setup_log_sinks(configuration_file)
+
+    fastapi_kwargs = load_configuration(configuration_file)["fastapi"]
+    logger.info("Creating FastAPI App", lifespan=lifespan, **fastapi_kwargs)
     app = FastAPI(**fastapi_kwargs, lifespan=lifespan)
 
+    logger.info("Setting up middleware and exception handlers.")
+    # Order matters! Each added middleware wraps the previous, creating a stack.
+    # See also: https://fastapi.tiangolo.com/tutorial/middleware/#multiple-middleware-execution-order
+    app.middleware("http")(request_response_logger)
+    app.middleware("http")(add_request_context_to_log)
+
     app.add_exception_handler(ProblemDetailError, problem_detail_exception_handler)  # type: ignore[arg-type]
 
+    logger.info("Adding routers to app")
     app.include_router(datasets_router)
     app.include_router(qualities_router)
     app.include_router(mldcat_ap_router)
@@ -72,11 +88,13 @@ def create_api() -> FastAPI:
     app.include_router(study_router)
     app.include_router(setup_router)
     app.include_router(run_router)
+
+    logger.info("App setup completed.")
+    logger.remove(setup_sink)
     return app
 
 
 def main() -> None:
-    logging.basicConfig(level=logging.INFO)
     args = _parse_args()
     uvicorn.run(
         app="main:create_api",

tests/config.test.toml

@@ -0,0 +1,28 @@
+arff_base_url="https://test.openml.org"
+minio_base_url="https://openml1.win.tue.nl"
+
+[development]
+allow_test_api_keys=true
+
+[logging.develop]
+sink="sys.stderr"
+level="DEBUG"
+
+[fastapi]
+root_path=""
+
+[databases.defaults]
+host="database"
+port="3306"
+# SQLAlchemy `dialect` and `driver`: https://docs.sqlalchemy.org/en/20/dialects/index.html
+drivername="mysql+aiomysql"
+
+[databases.expdb]
+database="openml_expdb"
+
+[databases.openml]
+database="openml"
+
+[routing]
+minio_url="http://minio:9000/"
+server_url="http://php-api:80/"

tests/conftest.py

@@ -73,7 +73,7 @@ async def php_api() -> AsyncIterator[httpx.AsyncClient]:
 async def py_api(
     expdb_test: AsyncConnection, user_test: AsyncConnection
 ) -> AsyncIterator[httpx.AsyncClient]:
-    app = create_api()
+    app = create_api(Path(__file__).parent / "config.test.toml")
 
     # We use async generator functions because fixtures may not be called directly.
     # The async generator returns the test connections for FastAPI to handle properly