from __future__ import annotations import ctypes import os import time from typing import Callable from fastapi import FastAPI, Request class _ProcessMemoryCounters(ctypes.Structure): _fields_ = [ ("cb", ctypes.c_ulong), ("PageFaultCount", ctypes.c_ulong), ("PeakWorkingSetSize", ctypes.c_size_t), ("WorkingSetSize", ctypes.c_size_t), ("QuotaPeakPagedPoolUsage", ctypes.c_size_t), ("QuotaPagedPoolUsage", ctypes.c_size_t), ("QuotaPeakNonPagedPoolUsage", ctypes.c_size_t), ("QuotaNonPagedPoolUsage", ctypes.c_size_t), ("PagefileUsage", ctypes.c_size_t), ("PeakPagefileUsage", ctypes.c_size_t), ] def _get_process_cpu_seconds() -> float: cpu_times = os.times() return cpu_times.user + cpu_times.system def _get_process_rss_bytes() -> int | None: if os.name == "nt": try: kernel32 = ctypes.WinDLL("kernel32", use_last_error=True) psapi = ctypes.WinDLL("psapi", use_last_error=True) kernel32.GetCurrentProcess.restype = ctypes.c_void_p psapi.GetProcessMemoryInfo.argtypes = [ctypes.c_void_p, ctypes.c_void_p, ctypes.c_ulong] psapi.GetProcessMemoryInfo.restype = ctypes.c_int counters = _ProcessMemoryCounters() counters.cb = ctypes.sizeof(_ProcessMemoryCounters) ok = psapi.GetProcessMemoryInfo( kernel32.GetCurrentProcess(), ctypes.byref(counters), counters.cb, ) if ok: return int(counters.WorkingSetSize) except Exception: return None return None try: with open("/proc/self/statm", "r", encoding="ascii") as handle: resident_pages = int(handle.read().split()[1]) return resident_pages * os.sysconf("SC_PAGE_SIZE") except Exception: return None def _format_megabytes(value: int | None) -> str: if value is None: return "unknown" return f"{value / (1024 * 1024):.1f}" def _format_megabyte_delta(start: int | None, end: int | None) -> str: if start is None or end is None: return "unknown" return f"{(end - start) / (1024 * 1024):.1f}" def _get_caller(request: Request) -> str: forwarded_for = request.headers.get("x-forwarded-for") if forwarded_for: return forwarded_for.split(",", 1)[0].strip() if request.client is not None: return request.client.host return "unknown" def install_request_logging(app: FastAPI, logger, service_name: str) -> None: @app.middleware("http") async def log_request(request: Request, call_next: Callable): started_at = time.perf_counter() cpu_started = _get_process_cpu_seconds() rss_started = _get_process_rss_bytes() caller = _get_caller(request) forwarded_for = request.headers.get("x-forwarded-for", "-") user_agent = request.headers.get("user-agent", "-") request_id = request.headers.get("x-request-id") or request.headers.get("x-correlation-id") or "-" content_length = request.headers.get("content-length", "0") error_type = "-" status_code = 500 logger.info( "incoming_request service=%s caller=%s forwarded_for=%s method=%s path=%s query=%s user_agent=%r request_id=%s content_length=%s", service_name, caller, forwarded_for, request.method, request.url.path, request.url.query or "-", user_agent, request_id, content_length, ) try: response = await call_next(request) status_code = response.status_code return response except Exception as exc: error_type = type(exc).__name__ raise finally: elapsed_ms = (time.perf_counter() - started_at) * 1000 cpu_time_ms = max(0.0, (_get_process_cpu_seconds() - cpu_started) * 1000) cpu_percent = 0.0 if elapsed_ms <= 0 else (cpu_time_ms / elapsed_ms) * 100 rss_finished = _get_process_rss_bytes() logger.info( "completed_request service=%s caller=%s method=%s path=%s status_code=%s response_time_ms=%.1f cpu_time_ms=%.1f cpu_percent=%.1f rss_mb=%s rss_delta_mb=%s request_id=%s error_type=%s", service_name, caller, request.method, request.url.path, status_code, elapsed_ms, cpu_time_ms, cpu_percent, _format_megabytes(rss_finished), _format_megabyte_delta(rss_started, rss_finished), request_id, error_type, )