Version 0.3.0

Changes:
- fix double exception message in main request_processing span
- add OpenSearch to Jaeger and OpenTelemetry Logs
- add optional OpenTelemetry Logs Exporter to structlog
- update deploy README

README.md

@@ -2,7 +2,7 @@
 
 This is a repository which contains a template for a backend python microservice running a FastAPI framework
 
-Version 0.2.0
+Version 0.3.0
 
 ## Usage
 

README.md.jinja

@@ -6,5 +6,9 @@
 
 Commands can be found in [Makefile](./Makefile)
 
-To initialize virtual environment and dependencies, run `make install-dev`
+To initialize virtual environment and dependencies, run `make install-dev`.
-To get a config example run `make config-example`, to run the application - `make run`
+To get a config example run `make config-example`, to run the application - `make run`.
+
+## run with sample infrastructure
+
+[Deploy directory](./deploy/) contains README and docker-compose file to start the server in one command with logging, metrics and tracing.

deploy/Makefile

@@ -0,0 +1,6 @@
+up:
+	docker compose up --build -d
+	docker compose down database-init prometheus-init grafana-init opensearch-init migrator
+
+down:
+	docker compose down

deploy/configs/api.yaml.jinja

@@ -15,9 +15,13 @@ db:
     user: postgres
     password: "!env(DB_PASSWORD)"
     pool_size: 2
-logging:
-  level: INFO
 observability:
+  logging:
+    level: INFO
+    exporter:
+      endpoint: http://otel:4317
+      level: INFO
+      tls_insecure: true
   prometheus:
     host: 0.0.0.0
     port: 9090

deploy/configs/jaeger-opensearch.yaml

@@ -0,0 +1,36 @@
+service:
+  extensions: [jaeger_storage, jaeger_query]
+  pipelines:
+    traces:
+      receivers: [otlp]
+      processors: [batch]
+      exporters: [jaeger_storage_exporter]
+
+extensions:
+  jaeger_query:
+    storage:
+      traces: opensearch_trace_storage
+      metrics: opensearch_trace_storage
+  jaeger_storage:
+    backends:
+      opensearch_trace_storage: &opensearch_config
+        opensearch:
+          server_urls:
+            - http://opensearch:9200
+    metric_backends:
+      opensearch_trace_storage: *opensearch_config
+
+receivers:
+  otlp:
+    protocols:
+      grpc:
+        endpoint: "0.0.0.0:4317"
+      http:
+        endpoint: "0.0.0.0:4318"
+
+processors:
+  batch:
+
+exporters:
+  jaeger_storage_exporter:
+    trace_storage: opensearch_trace_storage

deploy/configs/jaeger-ui.json

@@ -0,0 +1,8 @@
+{
+    "monitor": {
+        "menuEnabled": true
+    },
+    "dependencies": {
+        "menuEnabled": true
+    }
+}

deploy/configs/otel.yaml.jinja

@@ -13,6 +13,24 @@ exporters:
       insecure: true
   debug:
     verbosity: detailed
+  prometheusremotewrite:
+    endpoint: http://prometheus-pushgateway:9091/api/prom/push
+    tls:
+      insecure: true
+  opensearch:
+    http:
+      endpoint: http://opensearch:9200
+    # Logs configuration
+    logs_index: "otel-logs-%{service.name}"
+    logs_index_fallback: "default-service"
+    logs_index_time_format: "yyyy.MM.dd"
+    # Traces configuration
+    # traces_index: "otel-traces-%{service.name}"
+    # traces_index_fallback: "default-service"
+    # traces_index_time_format: "yyyy.MM.dd"
+    sending_queue:
+      batch:
+
 
 processors:
   batch:
@@ -24,7 +42,16 @@ service:
       exporters: [debug, otlp/jaeger]
     metrics:
       receivers: [otlp]
-      exporters: [debug]
+      exporters: [debug, prometheusremotewrite]
     logs:
       receivers: [otlp]
-      exporters: [debug]
+      exporters: [debug, opensearch]
+
+  telemetry:
+    metrics:
+      readers:
+        - pull:
+            exporter:
+              prometheus:
+                host: '0.0.0.0'
+                port: 8888

deploy/configs/prometheus.yml.jinja

@@ -11,3 +11,12 @@ scrape_configs:
     static_configs:
       - targets:
         - "{{project_name}}:9090"
+  - job_name: otel
+    static_configs:
+      - targets:
+          - "otel:8888"
+  - job_name: 'pushgateway'
+    honor_labels: true
+    static_configs:
+      - targets:
+          - "prometheus-pushgateway:9091"

deploy/docker-compose.yaml.jinja

@@ -4,7 +4,7 @@ services:
   # postgres database
 
   database-init:
-    image: postgres:17
+    image: postgres:17 # or postgis/postgis:17-3.5
     container_name: {{project_slug}}_db-init
     volumes: &postgres-volumes
       - ./data/postgres:/var/lib/postgresql/data
@@ -74,7 +74,7 @@ services:
       otel: # optional
         condition: service_started
     healthcheck:
-      test: ["CMD", "curl", "-f", "http://localhost:${PORT:-8080}/health_check/ping"]
+      test: ["CMD-SHELL", "curl -f http://localhost:${PORT:-8080}/health_check/ping"]
       interval: 10s
       timeout: 5s
       start_period: 5s
@@ -83,30 +83,41 @@ services:
   # prometheus + grafana monitoring
 
   prometheus-init:
-    image: prom/prometheus:latest
+    image: alpine:3.23
     container_name: prometheus-init
     volumes: &prometheus-volumes-section
       - ./configs/prometheus.yml:/etc/prometheus/prometheus.yml
       - ./data/prometheus:/prometheus
-    entrypoint: ["chown", "-R", "65534:65534", "/prometheus"]
+    entrypoint: ["chown", "65534:65534", "-R", "/prometheus"]
     user: "root"
 
+  prometheus-pushgateway:
+    image: prom/pushgateway:latest
+    container_name: prometheus-pushgateway
+    restart: unless-stopped
+    # ports:
+    #   - 9091:9091
+    logging: *json-logging
+
   prometheus:
     image: prom/prometheus:latest
     container_name: prometheus
     restart: unless-stopped
     ports:
       - 9090:9090
+    depends_on:
+      prometheus-init:
+        condition: service_completed_successfully
     volumes: *prometheus-volumes-section
     logging: *json-logging
 
   grafana-init:
-    image: grafana/grafana-enterprise:latest
+    image: alpine:3.23
     container_name: grafana-init
     volumes: &grafana-volumes-section
       - ./data/grafana:/var/lib/grafana
     user: "root"
-    entrypoint: ["chown", "-R", "472:0", "/var/lib/grafana"]
+    entrypoint: ["chown", "472:0", "-R", "/var/lib/grafana"]
 
   grafana:
     image: grafana/grafana-enterprise:latest
@@ -122,25 +133,74 @@ services:
 
   # jaeger tracing
 
+  opensearch-init:
+    image: alpine:3.23
+    volumes: &opensearch-volumes-section
+      - ./data/opensearch:/usr/share/opensearch/data
+    entrypoint: ["chown", "1000:1000", "-R", "/usr/share/opensearch/data"]
+    user: "root"
+
+  opensearch:
+    image: opensearchproject/opensearch:3.3.0@sha256:d96afaf6cbd2a6a3695aeb2f1d48c9a16ad5c8918eb849e5cbf43475f0f8e146
+    container_name: opensearch
+    environment:
+      - discovery.type=single-node
+      - plugins.security.disabled=true
+      - http.host=0.0.0.0
+      - transport.host=127.0.0.1
+      - OPENSEARCH_INITIAL_ADMIN_PASSWORD=admin-Password-1@-goes-here
+    # ports:
+    #   - 9200:9200 # REST API
+      # - 9600:9600 # Performance Analyzer
+    volumes: *opensearch-volumes-section
+    healthcheck:
+      test: [ "CMD-SHELL", "curl -f http://localhost:9200 || exit 1" ]
+      interval: 10s
+      timeout: 10s
+      retries: 30
+    logging: *json-logging
+
+  # # Visualizer for opensearch data
+  # opensearch-dashboards:
+  #   image: opensearchproject/opensearch-dashboards:latest
+  #   container_name: marketplace_os_dashboards
+  #   ports:
+  #     - 5601:5601
+  #   # expose:
+  #   #   - "5601"
+  #   environment:
+  #     OPENSEARCH_HOSTS: '["http://opensearch:9200"]'
+  #     DISABLE_SECURITY_DASHBOARDS_PLUGIN: "true"
+  #   depends_on:
+  #     opensearch:
+  #       condition: service_healthy
+
   jaeger:
     container_name: jaeger
-    image: cr.jaegertracing.io/jaegertracing/jaeger:2.11.0
+    image: cr.jaegertracing.io/jaegertracing/jaeger:2.12.0
     ports:
       - 16686:16686
       # - 5778:5778
       # - 9411:9411
+    volumes:
+      - ./configs/jaeger-ui.json:/etc/jaeger/jaeger-ui.json
+      - ./configs/jaeger-opensearch.yaml:/etc/jaeger/config.yml
+    command: ["--config", "/etc/jaeger/config.yml"]
+    depends_on:
+      opensearch:
+        condition: service_healthy
     restart: unless-stopped
     logging: *json-logging
     
   otel:
     container_name: otel
-    image: otel/opentelemetry-collector
+    image: otel/opentelemetry-collector-contrib
     # ports:
     #   - 4317:4317
     #   - 4318:4318
     restart: unless-stopped
     volumes:
-      - ./configs/otel.yaml:/etc/otelcol/config.yaml 
+      - ./configs/otel.yaml:/etc/otelcol-contrib/config.yaml
     depends_on:
       - jaeger
     logging: *json-logging

pyproject.toml.jinja

@@ -15,9 +15,10 @@ dependencies = [
     "pyyaml (>=6.0.3,<7.0.0)",
     "uvicorn (>=0.38.0,<0.39.0)",
     "asyncpg (>=0.30.0,<0.31.0)",
+    "opentelemetry-exporter-otlp (>=1.38,<2.0)",
     "opentelemetry-exporter-prometheus (>=0.59b0,<0.60)",
-    "opentelemetry-exporter-otlp-proto-http (>=1.38.0,<2.0.0)",
     "opentelemetry-semantic-conventions (>=0.59b0,<0.60)",
+    "opentelemetry-instrumentation-logging (>=0.59b0,<0.60)",
     "aiohttp (>=3.13.2,<4.0.0)",
     "email-validator (>=2.3.0,<3.0.0)",
     "pyjwt (>=2.10.1,<3.0.0)",

{{project_slug}}/__main__.py.jinja

@@ -100,7 +100,7 @@ def launch(
     config.app.host = host or config.app.host
     config.app.port = port or config.app.port
     config.app.debug = debug or config.app.debug
-    config.logging = config.logging if logger_verbosity is None else LoggingConfig(level=logger_verbosity)
+    config.observability.logging = config.observability.logging if logger_verbosity is None else LoggingConfig(level=logger_verbosity)
 
     with tempfile.NamedTemporaryFile(delete=False) as temp_file:
         temp_yaml_config_path = temp_file.name
@@ -113,7 +113,7 @@ def launch(
         uvicorn_config = {
             "host": config.app.host,
             "port": config.app.port,
-            "log_level": config.logging.level.lower(),
+            "log_level": config.observability.logging.level.lower(),
             "env_file": temp_envfile_path,
         }
         if config.app.debug:

{{project_slug}}/config.py.jinja

@@ -9,10 +9,9 @@ from typing import Any, Literal, TextIO, Type
 import yaml
 
 from {{project_slug}}.db.config import DBConfig, MultipleDBsConfig
+from {{project_slug}}.utils.observability import LoggingConfig, FileLogger, ExporterConfig
 from {{project_slug}}.utils.secrets import SecretStr, representSecretStrYAML
 
-from .utils.observability import LoggingLevel
-
 
 @dataclass
 class CORSConfig:
@@ -30,22 +29,6 @@ class AppConfig:
     cors: CORSConfig
 
 
-@dataclass
-class FileLogger:
-    filename: str
-    level: LoggingLevel
-
-
-@dataclass
-class LoggingConfig:
-    level: LoggingLevel
-    files: list[FileLogger] = field(default_factory=list)
-
-    def __post_init__(self):
-        if len(self.files) > 0 and isinstance(self.files[0], dict):
-            self.files = [FileLogger(**f) for f in self.files]
-
-
 @dataclass
 class PrometheusConfig:
     host: str
@@ -60,6 +43,7 @@ class JaegerConfig:
 
 @dataclass
 class ObservabilityConfig:
+    logging: LoggingConfig
     prometheus: PrometheusConfig | None = None
     jaeger: JaegerConfig | None = None
 
@@ -68,7 +52,6 @@ class ObservabilityConfig:
 class {{ProjectName}}Config:
     app: AppConfig
     db: MultipleDBsConfig
-    logging: LoggingConfig
     observability: ObservabilityConfig
 
     def to_order_dict(self) -> OrderedDict:
@@ -134,8 +117,13 @@ class {{ProjectName}}Config:
                     )
                 ],
             ),
-            logging=LoggingConfig(level="INFO", files=[FileLogger(filename="logs/info.log", level="INFO")]),
             observability=ObservabilityConfig(
+                logging=LoggingConfig(
+                    level="INFO",
+                    root_logger_level="INFO",
+                    exporter=ExporterConfig(endpoint="http://127.0.0.1:4317", level="INFO", tls_insecure=True),
+                    files=[FileLogger(filename="logs/info.log", level="INFO")],
+                ),
                 prometheus=PrometheusConfig(host="0.0.0.0", port=9090, urls_mapping={"/api/debug/.*": "/api/debug/*"}),
                 jaeger=JaegerConfig(endpoint="http://127.0.0.1:4318/v1/traces"),
             ),

{{project_slug}}/fastapi_init.py.jinja

@@ -95,11 +95,24 @@ def get_app(prefix: str = "/api") -> FastAPI:
 
     application.state.config = app_config
 
-    exception_mapper = _get_exception_mapper(app_config.app.debug)
+    logger = configure_logging(
+        app_config.observability.logging,
+        tracing_enabled=app_config.observability.jaeger is not None,
+    )
     metrics = init_metrics()
-    metrics_dep.init_dispencer(application, metrics)
+    exception_mapper = _get_exception_mapper(app_config.app.debug)
+    connection_manager = PostgresConnectionManager(
+        master=app_config.db.master,
+        replicas=app_config.db.replicas,
+        logger=logger,
+        application_name=f"{{project_slug}}_{VERSION}",
+    )
     urls_mapper = URLsMapper(app_config.observability.prometheus.urls_mapping)
 
+    connection_manager_dep.init_dispencer(application, connection_manager)
+    metrics_dep.init_dispencer(application, metrics)
+    logger_dep.init_dispencer(application, logger)
+
     application.add_middleware(
         ObservabilityMiddleware,
         exception_mapper=exception_mapper,
@@ -108,7 +121,7 @@ def get_app(prefix: str = "/api") -> FastAPI:
     )
     application.add_middleware(
         ExceptionHandlerMiddleware,
-        debug=[False],  # reinitialized on startup
+        debug=[app_config.app.debug],
         exception_mapper=exception_mapper,
     )
 
@@ -122,20 +135,10 @@ async def lifespan(application: FastAPI):
     Initializes database connection in pass_services_dependencies middleware.
     """
     app_config: {{ProjectName}}Config = application.state.config
-    loggers_dict = {logger_config.filename: logger_config.level for logger_config in app_config.logging.files}
+    logger = logger_dep.obtain(application)
-    logger = configure_logging(app_config.logging.level, loggers_dict)
 
     await logger.ainfo("application is being configured", config=app_config.to_order_dict())
 
-    connection_manager = PostgresConnectionManager(
-        master=app_config.db.master,
-        replicas=app_config.db.replicas,
-        logger=logger,
-        application_name=f"{{project_slug}}_{VERSION}",
-    )
-    connection_manager_dep.init_dispencer(application, connection_manager)
-    logger_dep.init_dispencer(application, logger)
-
     for middleware in application.user_middleware:
         if middleware.cls == ExceptionHandlerMiddleware:
             middleware.kwargs["debug"][0] = app_config.app.debug

{{project_slug}}/middlewares/observability.py.jinja

@@ -47,9 +47,15 @@ class ObservabilityMiddleware(BaseHTTPMiddleware):  # pylint: disable=too-few-pu
     async def dispatch(self, request: Request, call_next):
         logger = logger_dep.obtain(request)
         _try_get_parent_span_id(request)
-        with _tracer.start_as_current_span("http-request") as span:
+        with _tracer.start_as_current_span("http-request", record_exception=False) as span:
             trace_id = hex(span.get_span_context().trace_id or randint(1, 1 << 63))[2:]
             span_id = span.get_span_context().span_id or randint(1, 1 << 31)
+            if trace_id == 0:
+                trace_id = format(randint(1, 1 << 63), "016x")
+                span_id = format(randint(1, 1 << 31), "032x")
+                logger = logger.bind(trace_id=trace_id, span_id=span_id)
+            logger_dep.attach_to_request(request, logger)
+
             span.set_attributes(
                 {
                     http_attributes.HTTP_REQUEST_METHOD: request.method,
@@ -58,8 +64,6 @@ class ObservabilityMiddleware(BaseHTTPMiddleware):  # pylint: disable=too-few-pu
                     "request_client": request.client.host,
                 }
             )
-            logger = logger.bind(trace_id=trace_id, span_id=span_id)
-            request.state.logger = logger
 
             await logger.ainfo(
                 "handling request",

{{project_slug}}/utils/observability.py

@@ -1,20 +1,56 @@
 """Observability helper functions are defined here."""
 
 import logging
+import platform
 import re
 import sys
+from dataclasses import dataclass, field
 from pathlib import Path
 from typing import Literal
 
 import structlog
 from opentelemetry import trace
+from opentelemetry._logs import set_logger_provider
+from opentelemetry.exporter.otlp.proto.grpc._log_exporter import OTLPLogExporter
+from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
+from opentelemetry.sdk._logs.export import BatchLogRecordProcessor
+from opentelemetry.sdk.resources import Resource
+from opentelemetry.util.types import Attributes
 
 LoggingLevel = Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"]
 
 
+@dataclass
+class ExporterConfig:
+    endpoint: str
+    level: LoggingLevel = "INFO"
+    tls_insecure: bool = False
+
+
+@dataclass
+class FileLogger:
+    filename: str
+    level: LoggingLevel
+
+
+@dataclass
+class LoggingConfig:
+    level: LoggingLevel
+    exporter: ExporterConfig | None
+    root_logger_level: LoggingLevel = "INFO"
+    files: list[FileLogger] = field(default_factory=list)
+
+    def __post_init__(self):
+        if len(self.files) > 0 and isinstance(self.files[0], dict):
+            self.files = [FileLogger(**f) for f in self.files]
+
+
 def configure_logging(
-    log_level: LoggingLevel, files: dict[str, LoggingLevel] | None = None, root_logger_level: LoggingLevel = "INFO"
+    config: LoggingConfig,
+    tracing_enabled: bool,
 ) -> structlog.stdlib.BoundLogger:
+    files = {logger_config.filename: logger_config.level for logger_config in config.files}
+
     level_name_mapping = {
         "DEBUG": logging.DEBUG,
         "INFO": logging.INFO,
@@ -22,25 +58,44 @@ def configure_logging(
         "ERROR": logging.ERROR,
         "CRITICAL": logging.CRITICAL,
     }
-    files = files or {}
+
+    log_level = level_name_mapping[config.level]
+
+    processors = [
+        structlog.contextvars.merge_contextvars,
+        structlog.stdlib.add_log_level,
+        structlog.stdlib.add_logger_name,
+        structlog.processors.TimeStamper(fmt="iso"),
+        structlog.processors.StackInfoRenderer(),
+        structlog.processors.format_exc_info,
+        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+    ]
+
+    if tracing_enabled:
+
+        def add_open_telemetry_spans(_, __, event_dict: dict):
+            span = trace.get_current_span()
+            if not span or not span.is_recording():
+                return event_dict
+
+            ctx = span.get_span_context()
+
+            event_dict["span_id"] = format(ctx.span_id, "016x")
+            event_dict["trace_id"] = format(ctx.trace_id, "032x")
+
+            return event_dict
+
+        processors.insert(len(processors) - 1, add_open_telemetry_spans)
 
     structlog.configure(
-        processors=[
+        processors=processors,
-            structlog.contextvars.merge_contextvars,
-            structlog.stdlib.add_log_level,
-            structlog.stdlib.add_logger_name,
-            structlog.processors.TimeStamper(fmt="iso"),
-            structlog.processors.StackInfoRenderer(),
-            structlog.processors.format_exc_info,
-            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
-        ],
         logger_factory=structlog.stdlib.LoggerFactory(),
         wrapper_class=structlog.stdlib.BoundLogger,
         cache_logger_on_first_use=True,
     )
 
     logger: structlog.stdlib.BoundLogger = structlog.get_logger("main")
-    logger.setLevel(level_name_mapping[log_level])
+    logger.setLevel(log_level)
 
     console_handler = logging.StreamHandler(sys.stderr)
     console_handler.setFormatter(
@@ -60,7 +115,29 @@ def configure_logging(
         file_handler.setLevel(level_name_mapping[level])
         root_logger.addHandler(file_handler)
 
-    root_logger.setLevel(root_logger_level)
+    root_logger.setLevel(config.root_logger_level)
+
+    if config.exporter is not None:
+        logger_provider = LoggerProvider(
+            resource=Resource.create(
+                {
+                    "service.name": "{{project_name}}",
+                    "service.instance.id": platform.node(),
+                }
+            ),
+        )
+        set_logger_provider(logger_provider)
+
+        otlp_exporter = OTLPLogExporter(endpoint=config.exporter.endpoint, insecure=config.exporter.tls_insecure)
+        logger_provider.add_log_record_processor(BatchLogRecordProcessor(otlp_exporter))
+
+        exporter_handler = AttrFilteredLoggingHandler(
+            level=config.exporter.level,
+            logger_provider=logger_provider,
+        )
+        # exporter_handler.setFormatter(structlog.stdlib.ProcessorFormatter(processor=structlog.processors.JSONRenderer()))
+        exporter_handler.setLevel(level_name_mapping[config.exporter.level])
+        logger.addHandler(exporter_handler)
 
     return logger
 
@@ -102,3 +179,15 @@ def get_span_headers() -> dict[str, str]:
         "X-Span-Id": str(ctx.span_id),
         "X-Trace-Id": str(ctx.trace_id),
     }
+
+
+class AttrFilteredLoggingHandler(LoggingHandler):
+    DROP_ATTRIBUTES = ["_logger"]
+
+    @staticmethod
+    def _get_attributes(record: logging.LogRecord) -> Attributes:
+        attributes = LoggingHandler._get_attributes(record)
+        for attr in AttrFilteredLoggingHandler.DROP_ATTRIBUTES:
+            if attr in attributes:
+                del attributes[attr]
+        return attributes