feat: logging enhancements (!32) · Merge requests · OOP / code / open-exposure-gateway

src/open_exposure_gateway/core/authorization.py

+4 −10

Changes for src/open_exposure_gateway/core/authorization.py: 4 added lines, 10 removed lines.
Original line number	Diff line number	Diff line
		@@ -15,24 +15,20 @@ logger = structlog.get_logger(__name__)
		class OperationRequirements:
		role: str
		scope: Optional[str] = None
		# False where the spec lets client-credentials callers skip the scope (QoD).
		scope_required_for_two_legged: bool = True


		# Keyed by "{METHOD} {route path template}"; scopes are the ones each CAMARA spec declares.
		OPERATION_REQUIREMENTS: dict[str, OperationRequirements] = {
		# Quality on Demand
		"POST /qod/v0/sessions": OperationRequirements(
		"app-provider", scope="qod-sessions-write", scope_required_for_two_legged=False
		),
		"POST /qod/v0/sessions": OperationRequirements("app-provider", scope="qod-sessions-write"),
		"GET /qod/v0/sessions/{sessionId}": OperationRequirements(
		"app-provider", scope="qod-sessions-read", scope_required_for_two_legged=False
		"app-provider", scope="qod-sessions-read"
		),
		"DELETE /qod/v0/sessions/{sessionId}": OperationRequirements(
		"app-provider", scope="qod-sessions-delete", scope_required_for_two_legged=False
		"app-provider", scope="qod-sessions-delete"
		),
		"POST /qod/v0/sessions/{sessionId}/extend": OperationRequirements(
		"app-provider", scope="qod-sessions-write", scope_required_for_two_legged=False
		"app-provider", scope="qod-sessions-write"
		),
		"GET /qod/v0/qos-profiles": OperationRequirements("app-provider"),
		"GET /qod/v0/qos-profiles/{name}": OperationRequirements("app-provider"),
		@@ -156,8 +152,6 @@ def require_scope(
		requirements = _requirements_for(request)
		if requirements.scope is None:
		return caller
		if not requirements.scope_required_for_two_legged:
		return caller
		if requirements.scope not in caller.scopes:
		if not settings.keycloak_settings.enforcement_enabled:
		logger.warning(

src/open_exposure_gateway/core/logging.py

+2 −1

Changes for src/open_exposure_gateway/core/logging.py: 2 added lines, 1 removed line.
Original line number	Diff line number	Diff line
		@@ -26,7 +26,8 @@ def configure_logging(log_level: str = "INFO") -> None:
		formatter = structlog.stdlib.ProcessorFormatter(
		processors=[
		structlog.stdlib.ProcessorFormatter.remove_processors_meta,
		structlog.dev.ConsoleRenderer(),
		structlog.processors.format_exc_info,
		structlog.processors.JSONRenderer(),
		],
		foreign_pre_chain=shared_processors,
		)

src/open_exposure_gateway/dependencies.py

+30 −8

Changes for src/open_exposure_gateway/dependencies.py: 30 added lines, 8 removed lines.
Original line number	Diff line number	Diff line
		@@ -74,6 +74,15 @@ class CallerContext:
		app_provider_id: str
		roles: list[str]
		scopes: list[str]
		client_id: Optional[str] = None


		def caller_log_fields(caller: CallerContext) -> dict[str, Optional[str]]:
		return {
		"tenant_id": caller.tenant_id,
		"app_provider_id": caller.app_provider_id,
		"client_id": caller.client_id,
		}


		def get_app_state(request: Request) -> AppState:
		@@ -97,14 +106,23 @@ _bearer_scheme = HTTPBearer(auto_error=False)
		logger = structlog.get_logger(__name__)


		def _unverified_caller_context(x_correlator: Optional[str]) -> CallerContext:
		def _remember_caller(request: Request, caller: CallerContext) -> CallerContext:
		request.state.caller = caller
		structlog.contextvars.bind_contextvars(**caller_log_fields(caller))
		return caller


		def _unverified_caller_context(request: Request) -> CallerContext:
		"""Stand-in caller used only while `enforcement_enabled` is False."""
		return CallerContext(
		x_correlator=x_correlator,
		return _remember_caller(
		request,
		CallerContext(
		x_correlator=x_correlator_header(request),
		tenant_id="unverified",
		app_provider_id="unverified",
		roles=[],
		scopes=[],
		),
		)


		@@ -121,7 +139,7 @@ async def get_caller_context(
		if enforcement_enabled:
		raise UnauthorizedException(message="Missing bearer token")
		logger.warning("auth_would_reject", reason="missing_bearer_token", path=request.url.path)
		return _unverified_caller_context(x_correlator_header(request))
		return _unverified_caller_context(request)

		try:
		decoded = await token_verifier.verify(credentials.credentials)
		@@ -129,12 +147,12 @@ async def get_caller_context(
		if enforcement_enabled:
		raise
		logger.warning("auth_would_reject", reason="invalid_token", path=request.url.path)
		return _unverified_caller_context(x_correlator_header(request))
		return _unverified_caller_context(request)
		except DownstreamServiceException:
		if enforcement_enabled:
		raise
		logger.warning("auth_would_reject", reason="jwks_unreachable", path=request.url.path)
		return _unverified_caller_context(x_correlator_header(request))
		return _unverified_caller_context(request)

		claims = decoded.claims
		subject = claims.get("sub")
		@@ -145,17 +163,21 @@ async def get_caller_context(
		raise UnauthorizedException(message="Access token has no subject")
		raise ForbiddenException(message="Access token has no roles")
		logger.warning("auth_would_reject", reason="missing_claims", path=request.url.path)
		return _unverified_caller_context(x_correlator_header(request))
		return _unverified_caller_context(request)

		# A user without an `organization` is a tenant of their own.
		tenant_id: str = claims.get("organization") or subject

		return CallerContext(
		return _remember_caller(
		request,
		CallerContext(
		x_correlator=x_correlator_header(request),
		tenant_id=tenant_id,
		app_provider_id=subject,
		roles=roles,
		scopes=claims.get("scope", "").split(),
		client_id=claims.get("azp"),
		),
		)

src/open_exposure_gateway/main.py

+26 −0

Changes for src/open_exposure_gateway/main.py: 26 added lines, 0 removed lines.
Original line number	Diff line number	Diff line
		import asyncio
		import time
		from collections.abc import AsyncGenerator, Awaitable, Callable
		from contextlib import asynccontextmanager, suppress
		from datetime import datetime, timedelta, timezone
		@@ -67,6 +68,7 @@ from open_exposure_gateway.application.services.quality_on_demand_service import
		)
		from open_exposure_gateway.core.config import get_settings
		from open_exposure_gateway.core.logging import configure_logging
		from open_exposure_gateway.dependencies import caller_log_fields
		from open_exposure_gateway.domain.edge_application_management import (
		SRMOperationCompleted,
		Subject,
		@@ -451,6 +453,9 @@ async def default_lifespan(app: FastAPI) -> AsyncGenerator[None, None]:
		logger.info("Database engine disposed")


		_PROBE_PATHS = frozenset({"/platform/healthz", "/platform/readyz"})


		def create_app(lifespan: Optional[Lifespan[FastAPI]] = None) -> FastAPI:
		"""Build the application.

		@@ -479,6 +484,27 @@ def create_app(lifespan: Optional[Lifespan[FastAPI]] = None) -> FastAPI:
		response.headers["x-correlator"] = x_correlator
		return response

		@app.middleware("http")
		async def log_request(
		request: Request, call_next: Callable[[Request], Awaitable[Response]]
		) -> Response:
		started = time.perf_counter()
		response = await call_next(request)
		logger = structlog.get_logger()
		log = logger.debug if request.url.path in _PROBE_PATHS else logger.info
		caller = getattr(request.state, "caller", None)
		route = request.scope.get("route")
		log(
		"http_request",
		method=request.method,
		path=getattr(route, "path", request.url.path),
		status=response.status_code,
		duration_ms=round((time.perf_counter() - started) * 1000, 1),
		x_correlator=x_correlator_header(request),
		**(caller_log_fields(caller) if caller else {}),
		)
		return response

		app.include_router(health_router, prefix="/platform")
		app.include_router(edge_application_management_router)
		app.include_router(quality_on_demand_router)

tests/unit/test_authorization.py

+34 −17

Changes for tests/unit/test_authorization.py: 34 added lines, 17 removed lines.
Original line number	Diff line number	Diff line
		@@ -7,6 +7,7 @@ produces."""
		from typing import Optional

		import pytest
		import structlog
		from fastapi import Request
		from fastapi.routing import APIRoute
		from fastapi.testclient import TestClient
		@@ -21,16 +22,17 @@ from open_exposure_gateway.core.exceptions import ForbiddenException
		from open_exposure_gateway.dependencies import CallerContext, get_caller_context
		from open_exposure_gateway.main import app

		_QOD_ROUTE = (
		"POST",
		"/qod/v0/sessions",
		) # scope: qod-sessions-write, two-legged exempt
		_QOD_ROUTE = ("POST", "/qod/v0/sessions")
		_QOD_SESSION_ROUTES = [
		("POST", "/qod/v0/sessions", "qod-sessions-write"),
		("GET", "/qod/v0/sessions/{sessionId}", "qod-sessions-read"),
		("DELETE", "/qod/v0/sessions/{sessionId}", "qod-sessions-delete"),
		("POST", "/qod/v0/sessions/{sessionId}/extend", "qod-sessions-write"),
		]
		_LOCATION_RETRIEVAL_ROUTE = (
		"POST",
		"/location-retrieval/v0.5/retrieve",
		) # scope: location-retrieval:read
		# EAM's openId scheme requires its scope -- unlike QoD's routes above.
		_SCOPE_ALWAYS_REQUIRED_ROUTE = ("GET", "/edge-application-management/v0.1alpha1/apps")
		_FEDERATION_ROUTE = ("POST", "/platform/v1/federation/partners/{partnerOpId}/federations")


		@@ -131,20 +133,35 @@ class TestRequireScope:
		caller = _caller(roles=["app-provider"], scopes=["location-retrieval:read"])
		assert require_scope(request, caller, _settings()) is caller

		def test_caller_is_exempt_on_a_qod_route(self) -> None:
		# QoD's spec offers oAuth2ClientCredentials (no scope) as an alternative to
		# threeLegged+scope -- a caller needs no scope at all here.
		request = _request(*_QOD_ROUTE)
		caller = _caller(roles=["app-provider"], scopes=[])
		@pytest.mark.parametrize(("method", "path", "scope"), _QOD_SESSION_ROUTES)
		def test_qod_session_route_without_its_scope_is_rejected(
		self, method: str, path: str, scope: str
		) -> None:
		request = _request(method, path)
		other_scopes = [s for _, _, s in _QOD_SESSION_ROUTES if s != scope]
		caller = _caller(roles=["app-provider"], scopes=other_scopes)
		with pytest.raises(ForbiddenException):
		require_scope(request, caller, _settings())

		@pytest.mark.parametrize(("method", "path", "scope"), _QOD_SESSION_ROUTES)
		def test_qod_session_route_with_its_scope_is_allowed(
		self, method: str, path: str, scope: str
		) -> None:
		request = _request(method, path)
		caller = _caller(roles=["app-provider"], scopes=[scope])
		assert require_scope(request, caller, _settings()) is caller

		def test_caller_still_needs_scope_on_an_eam_route(self) -> None:
		# EAM's openIdConnect scheme has no client-credentials alternative: the scope
		# is required.
		request = _request(*_SCOPE_ALWAYS_REQUIRED_ROUTE)
		def test_missing_qod_scope_is_logged_not_rejected_when_enforcement_disabled(self) -> None:
		request = _request(*_QOD_ROUTE)
		caller = _caller(roles=["app-provider"], scopes=[])
		with pytest.raises(ForbiddenException):
		require_scope(request, caller, _settings())
		with structlog.testing.capture_logs() as logs:
		result = require_scope(request, caller, _settings(enforcement_enabled=False))
		assert result is caller
		assert {
		"event": "authz_would_reject",
		"reason": "missing_scope",
		"required_scope": "qod-sessions-write",
		}.items() <= logs[0].items()

		def test_operation_with_no_declared_scope_is_allowed(self) -> None:
		# QoD's qos-profiles reads declare no scope in the spec at all.

feat: logging enhancements

Merge request reports