diff --git a/.env.example b/.env.example index a19857097..e891ed99d 100644 --- a/.env.example +++ b/.env.example @@ -84,3 +84,7 @@ IS_SCALAR_ENABLED=true # Feature flag that can be used to enable/disable performance profiling, # which can be activated via the `?profile=true` URL query parameter. IS_PROFILING_ENABLED=true + +# Feature flag that can be used to enable/disable the measurement and +# logging of HTTP response times to the console. +IS_RESPONSE_TIME_LOGGING_ENABLED=true diff --git a/nmdc_runtime/api/main.py b/nmdc_runtime/api/main.py index 56b827d33..03671ef50 100644 --- a/nmdc_runtime/api/main.py +++ b/nmdc_runtime/api/main.py @@ -20,7 +20,10 @@ from nmdc_runtime import config from nmdc_runtime.api.analytics import Analytics -from nmdc_runtime.api.middleware import PyinstrumentMiddleware +from nmdc_runtime.api.middleware import ( + PyinstrumentMiddleware, + ResponseTimeLoggerMiddleware, +) from nmdc_runtime.config import IS_SCALAR_ENABLED from nmdc_runtime.util import ( decorate_if, @@ -273,6 +276,9 @@ async def get_versions(): if config.IS_PROFILING_ENABLED: app.add_middleware(PyinstrumentMiddleware) +if config.IS_RESPONSE_TIME_LOGGING_ENABLED: + app.add_middleware(ResponseTimeLoggerMiddleware) + # Note: Here, we are mounting a `StaticFiles` instance (which is bound to the directory that # contains static files) as a "sub-application" of the main FastAPI application. This # makes the contents of that directory be accessible under the `/static` URL path. diff --git a/nmdc_runtime/api/middleware.py b/nmdc_runtime/api/middleware.py index fd4695808..4a52f3e46 100644 --- a/nmdc_runtime/api/middleware.py +++ b/nmdc_runtime/api/middleware.py @@ -1,3 +1,6 @@ +import logging +import time + from fastapi import Request from fastapi.responses import HTMLResponse from pyinstrument import Profiler @@ -41,3 +44,34 @@ async def dispatch(self, request: Request, call_next): else: # Allow the request to be processed as usual. return await call_next(request) + + +class ResponseTimeLoggerMiddleware(BaseHTTPMiddleware): + r""" + FastAPI middleware that logs the response time to the console. + + This function measures how long the application takes to process the current HTTP request, + and logs that duration to the console. It also logs the HTTP method and URL path of the request, + although it represents the query string (if any) as "?..." instead of representing it in full. + + Reference: https://fastapi.tiangolo.com/tutorial/middleware/#before-and-after-the-response + """ + + async def dispatch(self, request: Request, call_next): + start_time: float = time.perf_counter() + response = await call_next(request) + end_time: float = time.perf_counter() + duration_in_seconds = end_time - start_time + formatted_duration = f"{duration_in_seconds:.3f}" + + # Log the response time to the console. + # + # Note: We condense the query string (if any) to "?..." because we want the + # focal point of these messages to be the duration. Uvicorn's access + # logs already show the full query string. + # + query_string = "?..." if request.url.query != "" else "" + request_string = f"{request.method} {request.url.path}{query_string}" + logging.info(f'"{request_string}" response time (sec): {formatted_duration}') + + return response diff --git a/nmdc_runtime/config.py b/nmdc_runtime/config.py index f7de30b7b..1d7128f73 100644 --- a/nmdc_runtime/config.py +++ b/nmdc_runtime/config.py @@ -54,3 +54,9 @@ def is_env_var_true(name: str, default: str = "false") -> bool: # Feature flag that can be used to enable/disable performance profiling, # which can be activated via the `?profile=true` URL query parameter. IS_PROFILING_ENABLED: bool = is_env_var_true("IS_PROFILING_ENABLED", default="false") + +# Feature flag that can be used to enable/disable the measurement and +# logging of HTTP response times to the console. +IS_RESPONSE_TIME_LOGGING_ENABLED: bool = is_env_var_true( + "IS_RESPONSE_TIME_LOGGING_ENABLED", default="false" +)