Add middleware that logs HTTP response time to server console

.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

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.

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

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"
+)