Add JSON logging and Prometheus metrics from the service template

.env.sample

@@ -6,6 +6,10 @@ FRONTEND_HOST=http://localhost:5173
 # Environment: local, staging, production
 ENVIRONMENT=local
 
+# Logging: json is what the cluster expects, text is the readable form for local dev
+LOG_LEVEL=INFO
+LOG_FORMAT=text
+
 PROJECT_NAME='Rapid Evaluation Framework'
 
 # Backend

backend/pyproject.toml

@@ -11,7 +11,7 @@ dependencies = [
     "pydantic-settings<3.0.0,>=2.13.1",
     "sentry-sdk[fastapi]>=2.0.0",
     "climate-ref[aft-providers,postgres]>=0.18.0,<0.19",
-    "loguru",
+    "prometheus-fastapi-instrumentator>=7.0.0",
     "pyyaml>=6.0",
     "fastapi-sqlalchemy-monitor>=1.1.3",
 ]

backend/src/ref_backend/analytics.py

@@ -7,9 +7,12 @@
 so both deploy targets need to stay in step.
 """
 
+import logging
+
 import httpx
 from fastapi import APIRouter, Request, Response
-from loguru import logger
+
+logger = logging.getLogger(__name__)
 
 PLAUSIBLE_SCRIPT_URL = "https://plausible.io/js/script.file-downloads.outbound-links.js"
 PLAUSIBLE_EVENT_URL = "https://plausible.io/api/event"

backend/src/ref_backend/api/routes/aft.py

@@ -1,9 +1,12 @@
+import logging
+
 from fastapi import APIRouter, HTTPException
-from loguru import logger
 
 from ref_backend.core.aft import get_aft_diagnostic_by_id, get_aft_diagnostics_index
 from ref_backend.models import AFTDiagnosticDetail, AFTDiagnosticSummary
 
+logger = logging.getLogger(__name__)
+
 router = APIRouter(prefix="/cmip7-aft-diagnostics", tags=["CMIP7 Assessment Fast Track (AFT)"])
 
 

backend/src/ref_backend/api/routes/executions.py

@@ -1,3 +1,4 @@
+import logging
 import mimetypes
 import os
 import tarfile
@@ -7,7 +8,6 @@
 from typing import Literal
 
 from fastapi import APIRouter, HTTPException, Query, Request
-from loguru import logger
 from sqlalchemy import select
 from sqlalchemy.orm import Session
 from starlette.responses import StreamingResponse
@@ -39,6 +39,8 @@
 )
 from ref_backend.models.executions import EXECUTION_GROUP_LOAD_OPTIONS
 
+logger = logging.getLogger(__name__)
+
 router = APIRouter(prefix="/executions", tags=["executions"])
 
 

backend/src/ref_backend/api/routes/utils.py

@@ -10,11 +10,6 @@
 router = APIRouter(prefix="/utils", tags=["utils"])
 
 
-@router.get("/health-check/")
-async def health_check() -> bool:
-    return True
-
-
 @router.get("/about")
 async def about(session: SessionDep, settings: SettingsDep) -> About:
     """

backend/src/ref_backend/builder.py

@@ -1,11 +1,13 @@
+import logging
+from collections.abc import Callable
 from dataclasses import asdict
 
 import sentry_sdk
+import sqlalchemy
 from fastapi import FastAPI
 from fastapi.routing import APIRoute
 from fastapi_sqlalchemy_monitor import AlchemyStatistics, SQLAlchemyMonitor
 from fastapi_sqlalchemy_monitor.action import Action, ConditionalAction, WarnMaxTotalInvocation
-from loguru import logger
 from starlette.exceptions import HTTPException
 from starlette.middleware.cors import CORSMiddleware
 from starlette.responses import Response
@@ -17,6 +19,12 @@
 from ref_backend.analytics import router as analytics_router
 from ref_backend.api.main import api_router
 from ref_backend.core.config import Settings
+from ref_backend.deploy import router as deploy_router
+from ref_backend.health import router as health_router
+from ref_backend.metrics import instrument_app
+from ref_backend.middleware import WideEventMiddleware
+
+logger = logging.getLogger(__name__)
 
 description = """
 API for querying the results from the Climate Rapid Evaluation Framework (Climate REF).
@@ -33,6 +41,9 @@
 
 
 def custom_generate_unique_id(route: APIRoute) -> str:
+    # Untagged routes such as /metrics are not part of the client, so the bare name is enough.
+    if not route.tags:
+        return route.name
     return f"{route.tags[0]}-{route.name}"
 
 
@@ -63,6 +74,19 @@ def handle(self, statistics: AlchemyStatistics) -> None:
             logger.info(asdict(statistics))
 
 
+def _database_readiness_check(database: Database) -> Callable[[], bool]:
+    """
+    Build a readiness check that proves the configured database still answers
+    """
+
+    def database_reachable() -> bool:
+        with database._engine.connect() as connection:
+            connection.execute(sqlalchemy.text("SELECT 1"))
+        return True
+
+    return database_reachable
+
+
 class SPAStaticFiles(StaticFiles):
     """
     Static file handler with SPA fallback.
@@ -127,12 +151,22 @@ def build_app(settings: Settings, ref_config: Config, database: Database) -> Fas
             allow_credentials=False,
             allow_methods=["GET"],
             allow_headers=["*"],
+            expose_headers=["x-request-id", "x-process-time"],
         )
 
+    app.add_middleware(WideEventMiddleware)
+
+    app.state.readiness_checks = [_database_readiness_check(database)]
+
     app.include_router(api_router, prefix=settings.API_V1_STR)
 
     # Mounted above the static files, which only answer GET and HEAD.
     app.include_router(analytics_router)
+    app.include_router(health_router)
+    app.include_router(deploy_router)
+
+    # Registers /metrics, which has to be in place before the catch-all SPA mount below.
+    instrument_app(app)
 
     if settings.STATIC_DIR:
         logger.info(f"Serving static files from {settings.STATIC_DIR}")

backend/src/ref_backend/core/config.py

@@ -32,6 +32,13 @@ class Settings(BaseSettings):
     BACKEND_HOST: str = "http://localhost:8000"
     ENVIRONMENT: Literal["local", "staging", "production"] = "local"
     LOG_LEVEL: str = "INFO"
+    LOG_FORMAT: Literal["json", "text"] = "json"
+    """
+    Log line format.
+
+    ``json`` emits one parseable event per record. ``text`` is the human-readable form for local dev.
+    """
+
     DIAGNOSTIC_PROVIDERS: list[str] | None = None
     """
     Limit the diagnostics to only query the providers defined in this list.

backend/src/ref_backend/core/diagnostic_metadata.py

@@ -8,15 +8,17 @@
 """
 
 import functools
+import logging
 from collections.abc import Mapping
 from pathlib import Path
 from types import MappingProxyType
 from typing import Literal
 
 import yaml
-from loguru import logger
 from pydantic import BaseModel, Field
 
+logger = logging.getLogger(__name__)
+
 
 class ReferenceDatasetLink(BaseModel):
     """

backend/src/ref_backend/core/ref.py

@@ -1,12 +1,13 @@
+import logging
 from pathlib import Path
 
-from loguru import logger
-
 from climate_ref.config import Config
 from climate_ref.database import Database, MigrationState
 from climate_ref.provider_registry import ProviderRegistry
 from ref_backend.core.config import Settings
 
+logger = logging.getLogger(__name__)
+
 
 def get_ref_config(settings: Settings) -> Config:
     """

backend/src/ref_backend/deploy.py

@@ -0,0 +1,38 @@
+"""
+Route reporting what is actually deployed
+
+Not included in the schema: it is an operator diagnostic, not part of the public API.
+The build stamps here are the same values the wide events carry.
+"""
+
+import os
+from importlib.metadata import version
+
+from fastapi import APIRouter
+from pydantic import BaseModel
+
+router = APIRouter(prefix="/deploy", include_in_schema=False)
+
+
+class DeployInfo(BaseModel):
+    """
+    Information about the running deployment
+    """
+
+    version: str
+    git_commit: str | None
+    image_tag: str | None
+    build_time: str | None
+
+
+@router.get("/info")
+def deploy_info() -> DeployInfo:
+    """
+    Return the version and build stamps baked into the image
+    """
+    return DeployInfo(
+        version=version("ref-backend"),
+        git_commit=os.environ.get("GIT_COMMIT") or None,
+        image_tag=os.environ.get("IMAGE_TAG") or None,
+        build_time=os.environ.get("BUILD_TIME") or None,
+    )

backend/src/ref_backend/health.py

@@ -0,0 +1,52 @@
+"""
+Liveness and readiness probes
+
+Mounted at the root rather than under the versioned API, so an orchestrator can probe the
+process without knowing anything about the API surface.
+"""
+
+import inspect
+import logging
+
+from fastapi import APIRouter, HTTPException, Request
+
+logger = logging.getLogger(__name__)
+
+router = APIRouter(include_in_schema=False)
+
+
+@router.get("/livez")
+def liveness_probe() -> dict[str, str]:
+    """
+    Report process liveness without touching any dependency
+    """
+    return {"status": "alive"}
+
+
+@router.get("/readyz")
+async def readiness_probe(request: Request) -> dict[str, str]:
+    """
+    Report readiness by running the checks registered on ``app.state.readiness_checks``
+
+    Each check is a callable that returns a falsy value or raises to signal it is not ready.
+    A check may be async, in which case what it returns is awaited.
+    An empty (or unset) check list means the service is always ready.
+    """
+    checks = getattr(request.app.state, "readiness_checks", [])
+    failures: dict[str, str] = {}
+    for check in checks:
+        name = getattr(check, "__name__", repr(check))
+        try:
+            ok = check()
+            if inspect.isawaitable(ok):
+                ok = await ok
+        except Exception as exc:
+            logger.warning(f"Readiness check {name} failed", exc_info=True)
+            failures[name] = str(exc)
+            continue
+        if not ok:
+            failures[name] = "check returned a falsy result"
+
+    if failures:
+        raise HTTPException(status_code=503, detail=failures)
+    return {"status": "ready"}