feat(api): use factory function for creating app, add structlog

api/pyproject.toml

@@ -1,5 +1,5 @@
 [tool.poetry]
-name = "DAMNIT-web API"
+name = "damnit-api"
 version = "0.1.0"
 description = ""
 authors = ["European XFEL <[email protected]>"]
@@ -31,6 +31,8 @@ pydantic-settings = "^2.2.1"
 async-lru = "^2.0.4"
 ldap3 = "^2.9.1"
 requests = "^2.32.3"
+structlog = "^24.4.0"
+colorama = "^0.4.6"
 
 [tool.poetry.group.test.dependencies]
 pytest = "^7.4.2"

api/src/damnit_api/__init__.py

@@ -0,0 +1,3 @@
+from structlog import get_logger
+
+__all__ = ["get_logger"]

api/src/damnit_api/_logging.py

@@ -0,0 +1,176 @@
+import logging
+import sys
+from typing import TYPE_CHECKING
+
+import colorama
+import structlog
+import structlog.typing
+from starlette.middleware.base import BaseHTTPMiddleware
+from structlog.stdlib import ProcessorFormatter
+
+if TYPE_CHECKING:  # pragma: no cover
+    from starlette.requests import Request
+    from starlette.responses import Response
+
+
+def logger_name_callsite(logger, method_name, event_dict):
+    if not event_dict.get("logger_name"):
+        logger_name = f"{event_dict.pop("module")}.{event_dict.pop("func_name")}"
+        if not event_dict.pop("disable_name", False):
+            event_dict["logger_name"] = logger_name.strip(".")  # pyright: ignore[reportInvalidTypeForm]
+
+    return event_dict
+
+
+def configure(
+    level: str | int | None = None,
+    debug: bool | None = None,
+    add_call_site_parameters: bool = False,
+) -> None:
+    """
+    Configures logging and sets up Uvicorn to use Structlog.
+    """
+
+    from .settings import settings
+
+    debug = settings.debug if debug is None else debug
+    level = settings.log_level if level is None else level
+
+    if isinstance(level, str):
+        level = logging.getLevelNamesMapping()[level.upper()]
+
+    level_styles = structlog.dev.ConsoleRenderer.get_default_level_styles()
+
+    if debug:
+        level_styles["debug"] = colorama.Fore.MAGENTA
+
+    renderer: structlog.typing.Processor = (
+        structlog.dev.ConsoleRenderer(colors=True, level_styles=level_styles)  # type: ignore[assignment]
+        if debug
+        else structlog.processors.JSONRenderer(indent=1)
+    )
+
+    # sentry_processor = sentry.SentryProcessor(level=level)
+
+    shared_processors: list[structlog.typing.Processor] = [
+        structlog.contextvars.merge_contextvars,
+        structlog.processors.add_log_level,
+        structlog.processors.StackInfoRenderer(),
+        structlog.dev.set_exc_info,
+        structlog.processors.TimeStamper(fmt="%Y-%m-%dT%H:%M:%SZ", utc=True),
+    ]
+
+    if add_call_site_parameters:
+        shared_processors.extend(
+            [
+                structlog.processors.CallsiteParameterAdder(
+                    {
+                        structlog.processors.CallsiteParameter.MODULE,
+                        structlog.processors.CallsiteParameter.FUNC_NAME,
+                    }
+                ),  # type: ignore[arg-type]
+                logger_name_callsite,
+            ]
+        )
+
+    structlog_processors = [*shared_processors, renderer]
+    logging_processors = [ProcessorFormatter.remove_processors_meta, renderer]
+
+    # if sentry.SENTRY_ENABLED:
+    #     processors.append(sentry_processor)
+
+    formatter = ProcessorFormatter(
+        foreign_pre_chain=shared_processors,
+        processors=logging_processors,
+    )
+
+    structlog.configure(
+        processors=structlog_processors,
+        wrapper_class=structlog.make_filtering_bound_logger(level),
+        logger_factory=structlog.PrintLoggerFactory(sys.stderr),
+        cache_logger_on_first_use=True,
+        context_class=dict,
+    )
+
+    handler = logging.StreamHandler(sys.stderr)
+    handler.setFormatter(formatter)
+    logging.basicConfig(handlers=[handler], level=logging.INFO)
+
+    configure_uvicorn(renderer, shared_processors)
+
+    log = structlog.get_logger()
+    log.info(
+        "Configured Logging",
+        call_site_parameters=add_call_site_parameters,
+        log_level=logging.getLevelName(level),
+    )
+
+
+def configure_uvicorn(renderer, shared_processors):
+    import uvicorn.config
+
+    uvicorn.config.LOGGING_CONFIG["formatters"]["default"] = {
+        "()": structlog.stdlib.ProcessorFormatter,
+        "processor": renderer,
+        "foreign_pre_chain": shared_processors,
+    }
+
+    uvicorn.config.LOGGING_CONFIG["handlers"]["default"] = {
+        "class": "logging.StreamHandler",
+        "formatter": "default",
+    }
+
+    uvicorn.config.LOGGING_CONFIG["root"] = {
+        "level": logging.INFO,
+        "handlers": ["default"],
+    }
+
+    # Disabled access log handlers as they are handled by the middleware
+    uvicorn.config.LOGGING_CONFIG["loggers"]["uvicorn.access"]["handlers"] = []
+
+
+class RequestLoggingMiddleware(BaseHTTPMiddleware):
+    _logger = None
+
+    @property
+    def logger(self):
+        if not self._logger:
+            self._logger = structlog.get_logger(disable_name=True)
+
+        return self._logger
+
+    async def dispatch(self, request: "Request", call_next) -> "Response":
+        """Add a middleware to FastAPI that will log requests and responses,
+        this is used instead of the builtin Uvicorn access logging to better
+        integrate with structlog"""
+        info = {
+            "method": request.method,
+            "path": request.scope["path"],
+            "client": request.client,
+        }
+
+        if request.query_params:
+            info["query_params"] = str(request.query_params)
+
+        if request.path_params:
+            info["path_params"] = str(request.path_params)
+
+        logger = self.logger.bind(path=request.scope["path"], method=request.method)
+        logger.debug("Request", **info)
+
+        response = await call_next(request)
+
+        if response.status_code < 400:
+            response_logger = logger.info
+        elif response.status_code < 500:
+            response_logger = logger.warn
+        else:
+            response_logger = logger.error
+
+        # Health checks are noisy, so we downgrade their log level
+        if request.url.path.endswith("/health"):
+            response_logger = logger.debug
+
+        response_logger("Response", status_code=response.status_code)
+
+        return response

api/src/damnit_api/auth/services.py

@@ -6,13 +6,16 @@
 from fastapi import Request
 from ldap3 import ALL, SUBTREE, Connection, Server
 
+from .. import get_logger
 from ..acl.models import ACL
 from ..metadata.proposals import (
     get_available_proposals,
     sort_proposals_by_run_cycle,
 )
 from .models import Group, Resource, User
 
+logger = get_logger()
+
 _LDAP_SERVER = "ldap://ldap.desy.de"  # TODO: put in config
 _LDAP_BASE = "ou=people,ou=rgy,o=DESY,c=DE"  # TODO: put in config
 _GROUP_NAME_RE = re.compile(r"cn=([^,]+)")
@@ -27,6 +30,16 @@ async def user_from_ldap(username: str) -> User:
     search_filter = f"(uid={username})"
     search_attributes = ["uidNumber", "cn", "mail", "isMemberOf"]
 
+    _logger = logger.bind(username=username)
+
+    _logger.debug(
+        "LDAP search for user",
+        ldap_bash=_LDAP_BASE,
+        search_filter=search_filter,
+        search_scope=SUBTREE,
+        attributes=search_attributes,
+    )
+
     loop = asyncio.get_event_loop()
     await loop.run_in_executor(
         None,
@@ -42,22 +55,29 @@ async def user_from_ldap(username: str) -> User:
         msg = "User not found"
         raise Exception(msg)  # TODO: better exception
 
+    _logger.debug("LDAP search result", entries=conn.entries)
+
     entry = conn.entries[0]
     name = entry.cn.value
     email = entry.mail.value
     uid = entry.uidNumber.value
 
     # CC: Prolly we shouldn't use return the actual groups,
     # but the proposals and the r/w access.
-    groups = [
-        _GROUP_NAME_RE.search(g).group(1)  # type: ignore[reportOptionalMemberAccess]
-        for g in entry.isMemberOf.value
-        if _GROUP_NAME_RE.search(g)
-    ]
+    groups = []
+    for g in entry.isMemberOf.value:
+        res = _GROUP_NAME_RE.search(g)
+
+        if not res:
+            _logger.debug("Group not found", group=g)
+            continue
+
+        groups.append(res.group(1))
+
     # For now, let's also include the list of proposals.
     proposals = get_available_proposals(groups)
 
-    return User(
+    user = User(
         uid=uid,
         username=username,
         name=name,
@@ -66,9 +86,16 @@ async def user_from_ldap(username: str) -> User:
         groups=[Group(gid=None, name=group) for group in groups],
     )
 
+    logger.debug("User from LDAP", user=user)
+
+    return user
+
 
 async def user_from_session(request: Request) -> User:
     user = request.session.get("user")
+
+    logger.debug("User from session", user=user)
+
     if not user:
         raise Exception  # TODO: better exception
 
@@ -81,4 +108,6 @@ async def resource_from_path(path: Path) -> Resource:
     owner = path.owner()
     group = path.group()
 
+    logger.debug("Resource from path", path=path, acl=acl, owner=owner, group=group)
+
     return Resource(path=path, acl=acl, owner=owner, group=group)