try structlog draft

app/config.py

@@ -3,22 +3,26 @@
 # from typing import Annotated
 # from pydantic import AfterValidator, HttpUrl
 # HttpUrlString = Annotated[HttpUrl, AfterValidator(str)]
+from .logging import CLogLevel
 
 
 class Settings(BaseSettings):
-    frontendschema: str = "http"
-    frontendhost: str = "localhost"
-    frontendport: int = 7000
-    frontendreload: bool = False
-
-    backendschema: str = "http"
-    backendhost: str = "localhost"
-    backendport: int = 8000
-    backendreload: bool = False
-    backendprefill: bool = False
+    frontend_schema: str = "http"
+    frontend_host: str = "localhost"
+    frontend_port: int = 7000
+    frontend_reload: bool = False
+    frontend_log_json_format: bool = False
+    frontend_log_level: CLogLevel = CLogLevel.INFO
+
+    backend_schema: str = "http"
+    backend_host: str = "localhost"
+    backend_port: int = 8000
+    backend_reload: bool = False
+    backend_prefill: bool = False
+    backend_log_json_format: bool = False
+    backend_log_level: CLogLevel = CLogLevel.INFO
 
     tz: str = "UTC"
-    secret_csrf: str
 
     model_config = SettingsConfigDict(env_file=".env", env_file_encoding="utf-8")
 

app/events.py

@@ -6,6 +6,7 @@
 from edgedb.asyncio_client import AsyncIOClient
 from fastapi import APIRouter, HTTPException, Query
 
+from .logging import CLogLevel, async_ep_log
 from .models import EventCreate, EventUpdate
 from .queries import create_event_async_edgeql as create_event_qry
 from .queries import delete_event_async_edgeql as delete_event_qry
@@ -38,9 +39,11 @@ async def get_events(
         if event := await get_event_by_name_qry.get_event_by_name(db_client, name=name):
             return event
 
+    err_msg = f"Event '{name}' does not exist."
+    await async_ep_log("api.events", err_msg, CLogLevel.WARNING)
     raise HTTPException(
         status_code=HTTPStatus.NOT_FOUND,
-        detail={"error": f"Event '{name}' does not exist."},
+        detail={"error": err_msg},
     )
 
 
@@ -65,18 +68,21 @@ async def post_event(
             db_client, **event.model_dump()
         )
     except edgedb.errors.InvalidArgumentError:
+        err_msg = """\
+                    Invalid datetime format. Datetime string must look like this: \n
+                    '2010-12-27T23:59:59-07:00'\
+                  """
+        await async_ep_log("api.events", err_msg, CLogLevel.WARNING)
         raise HTTPException(
             status_code=HTTPStatus.BAD_REQUEST,
-            detail={
-                "error": "Invalid datetime format. "
-                "Datetime string must look like this: "
-                "'2010-12-27T23:59:59-07:00'",
-            },
+            detail={"error": err_msg},
         )
     except edgedb.errors.ConstraintViolationError:
+        err_msg = f"Event name '{event.name}' already exists."
+        await async_ep_log("api.events", err_msg, CLogLevel.WARNING)
         raise HTTPException(
             status_code=HTTPStatus.BAD_REQUEST,
-            detail={"error": f"Event name '{event.name}' already exists."},
+            detail={"error": err_msg},
         )
     else:
         return created_event
@@ -102,24 +108,31 @@ async def put_event(
             db_client, **event.model_dump()
         )
     except edgedb.errors.InvalidArgumentError:
+        err_msg = """\
+                    Invalid datetime format. Datetime string must look like this: \n
+                    '2010-12-27T23:59:59-07:00'\
+                  """
+        await async_ep_log("api.events", err_msg, CLogLevel.WARNING)
         raise HTTPException(
             status_code=HTTPStatus.BAD_REQUEST,
-            detail={
-                "error": "Invalid datetime format. "
-                "Datetime string must look like this: '2010-12-27T23:59:59-07:00'",
-            },
+            detail={"error": err_msg},
         )
     except edgedb.errors.ConstraintViolationError:
+        err_msg = f"Event name '{event.name}' already exists."
+        await async_ep_log("api.events", err_msg, CLogLevel.WARNING)
         raise HTTPException(
             status_code=HTTPStatus.BAD_REQUEST,
-            detail={"error": f"Event name '{event.name}' already exists."},
+            detail={"error": err_msg},
         )
     else:
         if updated_event:
             return updated_event
+
+    err_msg = f"Update event '{event.name}' failed."
+    await async_ep_log("api.events", err_msg, CLogLevel.WARNING)
     raise HTTPException(
         status_code=HTTPStatus.INTERNAL_SERVER_ERROR,
-        detail={"error": f"Update event '{event.name}' failed."},
+        detail={"error": err_msg},
     )
 
 
@@ -141,7 +154,9 @@ async def delete_event(
     if deleted_event := await delete_event_qry.delete_event(db_client, name=name):
         return deleted_event
 
+    err_msg = f"Delete event '{name}' failed."
+    await async_ep_log("api.events", err_msg, CLogLevel.WARNING)
     raise HTTPException(
         status_code=HTTPStatus.INTERNAL_SERVER_ERROR,
-        detail={"error": f"Delete event '{name}' failed."},
+        detail={"error": err_msg},
     )

app/lifespan.py

@@ -40,7 +40,7 @@ def make_lifespan(*, prefill: bool):
     return svcs.fastapi.lifespan(partial(_lifespan, prefill=prefill))
 
 
-lifespan = make_lifespan(prefill=settings.backendprefill)
+lifespan = make_lifespan(prefill=settings.backend_prefill)
 
 ################################
 # Need to modify _tx_lifespan

app/logging.py

@@ -0,0 +1,98 @@
+import logging
+import sys
+from enum import StrEnum
+from typing import Any
+
+import structlog
+from structlog.types import EventDict, Processor  # noqa: F401
+
+
+class CLogLevel(StrEnum):
+    DEBUG = "debug"
+    INFO = "info"
+    WARNING = "warning"
+    FATAL = "fatal"
+    CRITICAL = "critical"
+
+
+async def async_ep_log(
+    logger_name: str, err_msg: str, level: CLogLevel = CLogLevel.WARNING
+) -> Any:
+    lgr = structlog.stdlib.get_logger(logger_name)
+    coro = getattr(lgr, f"a{level.lower()}")
+    await coro(err_msg)
+
+
+def ep_log(logger_name: str, err_msg: str, level: CLogLevel = CLogLevel.WARNING) -> Any:
+    lgr = structlog.stdlib.get_logger(logger_name)
+    func = getattr(lgr, level.lower())
+    func(err_msg)
+
+
+def setup_logging(json_logs: bool = False, log_level: CLogLevel = CLogLevel.INFO):
+    """see https://gist.github.com/nymous/f138c7f06062b7c43c060bf03759c29e"""
+    shared_processors: list[Processor] = [
+        structlog.contextvars.merge_contextvars,
+        structlog.stdlib.add_logger_name,
+        structlog.stdlib.add_log_level,
+        structlog.stdlib.PositionalArgumentsFormatter(),
+        structlog.stdlib.ExtraAdder(),
+        structlog.processors.TimeStamper(fmt="iso"),
+        structlog.processors.StackInfoRenderer(),
+    ]
+
+    if json_logs:
+        shared_processors.append(structlog.processors.format_exc_info)
+
+    structlog.configure(
+        processors=shared_processors
+        + [
+            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+        ],
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        cache_logger_on_first_use=True,  # Be careful for testing?
+    )
+
+    log_renderer: structlog.types.Processor
+    if json_logs:
+        log_renderer = structlog.processors.JSONRenderer()
+    else:
+        log_renderer = structlog.dev.ConsoleRenderer()
+
+    formatter = structlog.stdlib.ProcessorFormatter(
+        foreign_pre_chain=shared_processors,
+        processors=[
+            # Remove _record & _from_structlog.
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            log_renderer,
+        ],
+    )
+
+    handler = logging.StreamHandler()
+    handler.setFormatter(formatter)
+    root_logger = logging.getLogger()
+    root_logger.addHandler(handler)
+    root_logger.setLevel(log_level.upper())
+
+    for _log in ["uvicorn", "uvicorn.error"]:
+        logging.getLogger(_log).handlers.clear()
+        logging.getLogger(_log).propagate = True
+
+    logging.getLogger("uvicorn.access").handlers.clear()
+    logging.getLogger("uvicorn.access").propagate = False
+
+    def handle_exception(exc_type, exc_value, exc_traceback):
+        """
+        Log any uncaught exception instead of letting it be printed by Python
+        (but leave KeyboardInterrupt untouched to allow users to Ctrl+C to stop)
+        See https://stackoverflow.com/a/16993115/3641865
+        """
+        if issubclass(exc_type, KeyboardInterrupt):
+            sys.__excepthook__(exc_type, exc_value, exc_traceback)
+            return
+
+        root_logger.error(
+            "Uncaught exception", exc_info=(exc_type, exc_value, exc_traceback)
+        )
+
+    sys.excepthook = handle_exception

app/main.py

@@ -1,20 +1,25 @@
-import os
-import sys
-
-import uvicorn
+# import sys  # noqa: F401
+# sys.path.append(os.getcwd())
+# import uvicorn  # noqa: F401
+from asgi_correlation_id import CorrelationIdMiddleware
 from fastapi import FastAPI
 from starlette.middleware.cors import CORSMiddleware
 
-sys.path.append(os.getcwd())
-
 from app import common, events, health, users
 from app.config import settings
 from app.lifespan import lifespan
+from app.logging import setup_logging
+from app.middlewares import add_logging_middleware  # noqa: F401
+
+setup_logging(
+    json_logs=settings.backend_log_json_format, log_level=settings.backend_log_level
+)
 
 
 def make_app(lifespan):
     app = FastAPI(lifespan=lifespan)
 
+    app.middleware("http")(add_logging_middleware)
     app.add_middleware(
         CORSMiddleware,
         # allow_origins=[
@@ -25,6 +30,7 @@ def make_app(lifespan):
         allow_methods=["*"],
         allow_headers=["*"],
     )
+    app.add_middleware(CorrelationIdMiddleware)
 
     app.include_router(users.router)
     app.include_router(events.router)
@@ -36,11 +42,12 @@ def make_app(lifespan):
 
 app = make_app(lifespan)
 
-if __name__ == "__main__":
-    print(f"Backend: {settings=}")
-    uvicorn.run(
-        "main:app",
-        host=settings.backendhost,
-        port=settings.backendport,
-        reload=settings.backendreload,
-    )
+
+# if __name__ == "__main__":
+#     print(f"Backend: {settings=}")
+#     uvicorn.run(
+#         "main:app",
+#         host=settings.backendhost,
+#         port=settings.backendport,
+#         reload=settings.backendreload,
+#     )

app/middlewares.py

@@ -0,0 +1,46 @@
+import time
+
+import structlog
+from asgi_correlation_id.context import correlation_id
+from fastapi import Request, Response
+from uvicorn.protocols.utils import get_path_with_query_string
+
+
+async def add_logging_middleware(request: Request, call_next) -> Response:
+    api_access_logger = structlog.stdlib.get_logger("backend.access")
+    structlog.contextvars.clear_contextvars()
+    request_id = correlation_id.get()
+    structlog.contextvars.bind_contextvars(request_id=request_id)
+    start_time = time.perf_counter_ns()
+
+    response = Response(status_code=500)
+    try:
+        response = await call_next(request)
+    except Exception:
+        structlog.stdlib.get_logger("api.error").exception("Uncaught exception")
+        raise
+    finally:
+        process_time = time.perf_counter_ns() - start_time
+        status_code = response.status_code
+        url = get_path_with_query_string(request.scope)
+
+        # request.client is None for tests, so we need to fill in something here
+        client_host = getattr(request.client, "host", "testing_client_host")
+        client_port = getattr(request.client, "port", "testing_client_port")
+
+        http_method = request.method
+        http_version = request.scope["http_version"]
+        api_access_logger.info(
+            f"""{client_host}:{client_port} - "{http_method} {url} HTTP/{http_version}" {status_code}""",
+            http={
+                "url": str(request.url),
+                "status_code": status_code,
+                "method": http_method,
+                "request_id": request_id,
+                "version": http_version,
+            },
+            network={"client": {"ip": client_host, "port": client_port}},
+            duration=process_time,
+        )
+        response.headers["X-Process-Time"] = str(process_time / 10**9)
+        return response