Add middleware that logs HTTP response time to server console

[eecavanna]

On this branch, I introduced a new middleware (named ResponseTimeLoggerMiddleware), which—when enabled (by setting the IS_RESPONSE_TIME_LOGGING_ENABLED environment variable to true)—prints a line to the console log before the FastAPI application returns a response to Uvicorn. The line says how long the FastAPI application spent processing that request.

Details

Here's an example of a line (the first line here) printed by this middleware. The second line is printed by Uvicorn.

2025-09-12 23:48:24,721 - INFO - "GET /biosamples?..." response time (sec): 0.034
INFO:     172.18.0.1:62188 - "GET /biosamples?filter=ecosystem_category%3APlants%2C%20lat_lon.latitude%3A%3E35.0&per_page=25 HTTP/1.1" 200 OK

Note: My original desire was to append the response to the Uvicorn log line (instead of having an additional line). I didn't figure out how to do that, though, so I went with this approach instead. I think I'd still prefer the other approach, though, long term.

Related issue(s)

Fixes #1212

Related subsystem(s)

• Runtime API (except the Minter)
• Minter
• Dagster
• Project documentation (in the docs directory)
• Translators (metadata ingest pipelines)
• MongoDB migrations
• Other

Testing

• I tested these changes (explain below)
• I did not test these changes

I tested these changes by sending various HTTP requests to the FastAPI application—with and without query strings—and confirming the logs looked the way I wanted.

Documentation

• I have not checked for relevant documentation yet (e.g. in the docs directory)
• I have updated all relevant documentation so it will remain accurate
• Other (explain below)

Maintainability

• Every Python function I defined includes a docstring (test functions are exempt from this)
• Every Python function parameter I introduced includes a type hint (e.g. study_id: str)
• All "to do" or "fix me" Python comments I added begin with either # TODO or # FIXME
• I used black to format all the Python files I created/modified
• The PR title is in the imperative mood (e.g. "Do X") and not the declarative mood (e.g. "Does X" or "Did X")

[eecavanna]

Side note: I just noticed the home-grown Analytics middleware also computes a response time and includes it in the document it inserts into the _runtime.api.analytics collection.

nmdc-runtime/nmdc_runtime/api/analytics.py

Line 85 in 5a8065d

"response_time": int((time() - start) * 1000),

Comparison between the two middlewares:

Analytics	ResponseTimeLoggerMiddleware
Wider focus (response time is part of responsibility)	Narrower focus (response time is entire responsibility)
Stores response time in Mongo alongside more request metadata	Prints response time to console alongside less request metadata
Mongo field name lacks units (would be "ms")	Log message includes units (says "seconds")
Always enabled	Only enabled when env var set

The Analytics approach:

>>> start = time() ; sleep(1) ; print(int((time() - start) * 1000))
1005
>>> start = time() ; sleep(1) ; print(int((time() - start) * 1000))
1004
>>> start = time() ; sleep(1) ; print(int((time() - start) * 1000))
1000
>>> start = time() ; sleep(1) ; print(int((time() - start) * 1000))
1003

The ResponseTimeLoggerMiddleware approach:

>>> start = perf_counter() ; sleep(1) ; print(f"{perf_counter() - start:.3f} seconds")
1.001 seconds
>>> start = perf_counter() ; sleep(1) ; print(f"{perf_counter() - start:.3f} seconds")
1.000 seconds
>>> start = perf_counter() ; sleep(1) ; print(f"{perf_counter() - start:.3f} seconds")
1.005 seconds
>>> start = perf_counter() ; sleep(1) ; print(f"{perf_counter() - start:.3f} seconds")
1.005 seconds

Instead of introducing this separate middleware, we could just adjust the analytics middleware to (a) print the response time to the console (with units) and (b) only do that if the environment variable is set.