1+ """
2+ Structured logging setup, shared in shape across every FastAPI service in
3+ PriceLens (each service gets its own copy of this file -- there's no
4+ shared Python package across services in this project's architecture, so
5+ duplication here is the same deliberate tradeoff as the near-identical
6+ Dockerfiles from Phase 12: acceptable at this service count, would become
7+ a shared library at a larger scale).
8+
9+ Two things this solves that plain `logging.basicConfig` doesn't:
10+
11+ 1. JSON output -- a real log aggregation tool (Loki, CloudWatch, ELK) can
12+ parse and index individual fields (level, service, request_id) instead
13+ of needing to regex-parse a plain text line. This is what makes a query
14+ like "show me every ERROR from search-service in the last hour" fast
15+ and exact rather than approximate.
16+
17+ 2. Request correlation ID -- generated once per incoming HTTP request and
18+ attached to every log line produced while handling it, AND propagated
19+ to any outgoing call to another service (via the X-Request-ID header).
20+ This is what lets you grep one ID across auth-service, search-service,
21+ and the Celery worker's logs and see the complete story of one user's
22+ one request, rather than four separate unconnected timelines.
23+ """
24+ import json
25+ import logging
26+ import time
27+ import uuid
28+ from contextvars import ContextVar
29+
30+ from fastapi import Request
31+ from starlette .middleware .base import BaseHTTPMiddleware
32+
33+ # ContextVar (not a plain global) is what makes this safe under concurrent
34+ # async requests -- each request gets its own isolated value even though
35+ # they're all running in the same process/event loop, unlike a plain
36+ # module-level variable which would leak between concurrent requests.
37+ request_id_ctx : ContextVar [str ] = ContextVar ("request_id" , default = "-" )
38+
39+
40+ def get_current_request_id () -> str :
41+ """
42+ Used by outgoing HTTP clients (e.g. analytics-service's TrackingClient)
43+ to read the current request's correlation ID and forward it as an
44+ X-Request-ID header on calls to other services -- this is what makes
45+ the ID actually correlate across service boundaries, not just within
46+ one service's own logs.
47+ """
48+ return request_id_ctx .get ()
49+
50+
51+ class JsonFormatter (logging .Formatter ):
52+ def format (self , record : logging .LogRecord ) -> str :
53+ payload = {
54+ "timestamp" : self .formatTime (record , "%Y-%m-%dT%H:%M:%S%z" ),
55+ "level" : record .levelname ,
56+ "logger" : record .name ,
57+ "message" : record .getMessage (),
58+ "request_id" : request_id_ctx .get (),
59+ }
60+ if record .exc_info :
61+ payload ["exception" ] = self .formatException (record .exc_info )
62+ return json .dumps (payload )
63+
64+
65+ def configure_logging (service_name : str ) -> None :
66+ handler = logging .StreamHandler ()
67+ handler .setFormatter (JsonFormatter ())
68+
69+ root_logger = logging .getLogger ()
70+ root_logger .handlers = [handler ]
71+ root_logger .setLevel (logging .INFO )
72+
73+ # Tag every record with which service produced it -- useful once logs
74+ # from multiple services are aggregated into one stream/dashboard.
75+ old_factory = logging .getLogRecordFactory ()
76+
77+ def record_factory (* args , ** kwargs ):
78+ record = old_factory (* args , ** kwargs )
79+ record .service = service_name
80+ return record
81+
82+ logging .setLogRecordFactory (record_factory )
83+
84+
85+ class RequestIdMiddleware (BaseHTTPMiddleware ):
86+ """
87+ Reads X-Request-ID from an incoming request if present (meaning this
88+ request originated from, or passed through, another PriceLens service
89+ that already generated one), or creates a new one if this is the
90+ entry point. Either way, sets it in the ContextVar so every log line
91+ during this request includes it, and echoes it back in the response
92+ header so a client (or another service) can correlate further.
93+ """
94+
95+ async def dispatch (self , request : Request , call_next ):
96+ incoming_id = request .headers .get ("X-Request-ID" )
97+ req_id = incoming_id or str (uuid .uuid4 ())
98+ token = request_id_ctx .set (req_id )
99+
100+ start = time .monotonic ()
101+ try :
102+ response = await call_next (request )
103+ finally :
104+ request_id_ctx .reset (token )
105+
106+ duration_ms = round ((time .monotonic () - start ) * 1000 , 2 )
107+ response .headers ["X-Request-ID" ] = req_id
108+
109+ logging .getLogger ("access" ).info (
110+ "%s %s -> %s (%sms)" ,
111+ request .method ,
112+ request .url .path ,
113+ response .status_code ,
114+ duration_ms ,
115+ )
116+ return response
0 commit comments