Improves observability (#254)

* Make logger setup compatible with OTEL logs

* Remove direct structlog usage

* Replace base otel collector with grafana alloy

* Add note to README.md

Author: febus982

README.md

@@ -27,6 +27,7 @@ This template provides out of the box some commonly used functionalities:
 * Database migrations using [Alembic](https://alembic.sqlalchemy.org/en/latest/) (configured supporting both sync and async SQLAlchemy engines)
 * Database fixtures support using customized [Alembic](https://alembic.sqlalchemy.org/en/latest/) configuration
 * Authentication and Identity Provider using [ORY Zero Trust architecture](https://www.ory.sh/docs/kratos/guides/zero-trust-iap-proxy-identity-access-proxy)
+* Full observability setup using [OpenTelemetry](https://opentelemetry.io/) (Metrics, Traces and Logs)
 * Example CI/CD deployment pipeline for GitLab (The focus for this repository is still GitHub but, in case you want to use GitLab 🤷)
 * [TODO] Producer and consumer to emit and consume events using [CloudEvents](https://cloudevents.io/) format using HTTP, to be used with [Knative Eventing](https://knative.dev/docs/eventing/)
 

config.alloy

@@ -0,0 +1,29 @@
+otelcol.exporter.otlp "jaeger" {
+	client {
+		endpoint = "jaeger:4317"
+
+		tls {
+			insecure = true
+		}
+	}
+}
+
+otelcol.exporter.debug "console" {
+	verbosity = "Detailed"
+}
+
+otelcol.processor.batch "default" {
+	output {
+		traces = [otelcol.exporter.otlp.jaeger.input]
+	}
+}
+
+otelcol.receiver.otlp "default" {
+	grpc { }
+
+	output {
+		metrics = [otelcol.exporter.debug.console.input]
+		logs    = [otelcol.exporter.debug.console.input]
+		traces  = [otelcol.processor.batch.default.input]
+	}
+}

docker-compose.yaml

@@ -59,11 +59,19 @@ services:
       - "14268:14268" # HTTP port for spans
 
   otel-collector:
-    image: otel/opentelemetry-collector-contrib
+    image: grafana/alloy:latest
     depends_on:
       - jaeger
+    ports:
+      - "12345:12345"
     volumes:
-      - ./otel-collector-config.yaml:/etc/otelcol-contrib/config.yaml
+      - ./config.alloy:/etc/alloy/config.alloy
+    command:
+      - run
+      - --server.http.listen-addr=0.0.0.0:12345
+      - --stability.level=experimental
+#      - --stability.level=public-preview
+      - /etc/alloy/config.alloy
 
   redis:
     image: redis

local.env

@@ -2,3 +2,4 @@ ENVIRONMENT: "local"
 AUTH__JWKS_URL: "http://oathkeeper:4456/.well-known/jwks.json"
 #DRAMATIQ__REDIS_URL: "redis://redis:6379/0"
 OTEL_EXPORTER_OTLP_ENDPOINT: "http://otel-collector:4317"
+OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED: "true"

otel-collector-config.yaml

@@ -2,6 +2,7 @@
 from typing import List
 
 import structlog
+from opentelemetry.sdk._logs import LoggingHandler
 from structlog.typing import Processor
 
 from ..config import AppConfig
@@ -14,11 +15,22 @@
 
 def init_logger(config: AppConfig) -> None:
     """
-    Configure structlog and stdlib logging with shared handler and formatter.
+    Function to initialize logging configuration using `structlog` and Python's standard
+    logging module. It supports dynamic log level adjustment, shared processors for
+    structlog and standard loggers, and tailored configurations for different environments
+    (local, test, or production). Ensures consistent formatting across application logs
+    and integrates handlers for OpenTelemetry logs if present.
+
+    Args:
+        config (AppConfig): Configuration object containing application-wide settings
+        such as DEBUG flag and environment status.
+
+    Raises:
+        None
+
+    Returns:
+        None
 
-    :param config: The app configuration
-    :type config: AppConfig
-    :return:
     """
     # Strongly inspired by https://gist.github.com/nymous/f138c7f06062b7c43c060bf03759c29e
 
@@ -76,9 +88,17 @@ def init_logger(config: AppConfig) -> None:
         )
     )
 
-    # Use structlog to format logs coming from stdlib logger
+    # Get root logger
     stdlib_logger = logging.getLogger()
-    stdlib_logger.handlers.clear()
+
+    # In case there's a OTEL handler we keep it but remove all the others,
+    # in case this function is called multiple times.
+    # NOTE all the processors are not applied to OTEL logs!
+    for handler in stdlib_logger.handlers:
+        if not isinstance(handler, LoggingHandler):
+            stdlib_logger.removeHandler(handler)
+
+    # Use structlog to format logs coming from stdlib logger
     stdlib_logger.addHandler(stdlib_handler)
     stdlib_logger.setLevel(log_level)
 

src/common/logs/__init__.py

@@ -1,8 +1,8 @@
+import logging
 from collections.abc import Iterable
 
 from anyio import to_thread
 from dependency_injector.wiring import Provide, inject
-from structlog import get_logger
 
 from common.tracing import trace_function
 from common.utils import apply_decorator_to_methods
@@ -58,8 +58,12 @@ async def book_created_event_handler(
         book_id: int,
     ) -> None:  # pragma: no cover
         # This is just an example placeholder, there's nothing to test.
-        logger = get_logger()
-        await logger.ainfo(f"Processed book crated event for id `{book_id}`")
+        logging.info(
+            "Processed book crated event`",
+            extra={
+                "book_id": book_id,
+            },
+        )
 
     def _some_cpu_intensive_blocking_task(self, book: dict) -> dict:
         # This is just an example placeholder,

src/domains/books/_service.py

@@ -1,11 +1,8 @@
+import logging
+
 from cloudevents_pydantic.events import CloudEvent
-from structlog import get_logger
 
 
 class NullEventGateway:
     async def emit(self, event: CloudEvent) -> None:  # pragma: no cover # No need to test this
-        logger = get_logger()
-        await logger.ainfo(
-            "Event emitted",
-            cloudevent=event.model_dump(),
-        )
+        logging.info("Event emitted", extra={"cloudevent": event.model_dump()})

src/gateways/event.py

@@ -1,10 +1,10 @@
+import logging
 from typing import Union
 
 from fastapi import FastAPI, Request
 from opentelemetry.instrumentation.asgi import OpenTelemetryMiddleware
 from starlette.responses import JSONResponse
 from starlette_prometheus import PrometheusMiddleware, metrics
-from structlog import get_logger
 
 from common import AppConfig, application_init
 from http_app import context
@@ -62,6 +62,5 @@ async def add_exception_middleware(request: Request, call_next):
         try:
             return await call_next(request)
         except Exception as e:
-            logger = get_logger(__name__)
-            await logger.aexception(e)
+            logging.exception(e)
             return JSONResponse({"error": "Internal server error"}, status_code=500)

src/http_app/__init__.py

@@ -1,12 +1,12 @@
-from unittest.mock import AsyncMock, MagicMock, patch
+from unittest.mock import MagicMock, patch
 
 from fastapi import FastAPI
 from fastapi.testclient import TestClient
 
 
-@patch("http_app.get_logger")
+@patch("logging.exception")
 async def test_exception_is_logged_handler_returns_500(
-    mocked_get_logger: MagicMock,
+    mocked_logging_exception: MagicMock,
     testapp: FastAPI,
 ):
     my_exc = Exception("Some random exception")
@@ -15,12 +15,9 @@ async def test_exception_is_logged_handler_returns_500(
     async def fake_endpoint():
         raise my_exc
 
-    mocked_get_logger.return_value.aexception = AsyncMock(return_value=None)
-
     ac = TestClient(app=testapp, base_url="http://test")
     response = ac.get("/ppp")
 
     assert response.status_code == 500
     assert response.json() == {"error": "Internal server error"}
-    mocked_get_logger.assert_called_once()
-    mocked_get_logger.return_value.aexception.assert_called_once_with(my_exc)
+    mocked_logging_exception.assert_called_once_with(my_exc)