A follow-up to Counting OpenAI Tokens per Request in FastAPI.
I sent a document to evorag while the database was down.
OpenAI was called. The embedding was created. I paid for it.
Then the database write failed. The user got a 500.
My logs showed embedding.created. They did not show request.completed.
No status. No latency. No token count. The failed request was invisible.
That's the request I most needed to see.
In the last post, I built a logging middleware. This was its core:
metrics = start_metrics()
started = time.perf_counter()
response = await call_next(request)
latency_ms = round((time.perf_counter() - started) * 1000, 2)
logger.info("request.completed", ...)
I tested the happy path. I never tested a route that raises.
If the route raises, call_next raises. Every line below it is skipped. The log never runs.
So my request log had a blind spot. Successful requests were logged. Failed ones disappeared. Including the ones that had already cost money.
This time I wrote the test before the fix. A route that always raises. An assertion that request.completed is still logged.
It failed. Zero log records.
The tool is try/ finally. finally runs however the try block ends: normally, with return, or with an exception.
My first attempt:
status_code = 500
started = time.perf_counter()
try:
response = await call_next(request)
status_code = response.status_code
response.headers["x-request-id"] = request_id
return response
finally:
latency_ms = round((time.perf_counter() - started) * 1000, 2)
response.headers["x-request-id"] = request_id # bug 1
logger.info("request.completed", ...)
return response # bug 2
The test still failed. Both bugs were lines I had left over from the old version.
Bug 1. When the route fails, response never exists. That line raises UnboundLocalError. The log still never runs. Same bug, one line lower.
Bug 2 is the one worth remembering.
People usually say finally doesn't swallow exceptions. That's true. After finally finishes, the exception keeps going.
Unless you return inside finally:
def demo():
try:
raise ValueError("something broke")
finally:
return "everything is fine"
demo() # returns "everything is fine". No error.
The exception is silently discarded. In a middleware, that hides the real error from the framework. It's dangerous enough that Python 3.14 emits a warning for it, and ruff flags it too.
status_code = 500
started = time.perf_counter()
try:
response = await call_next(request)
status_code = response.status_code
response.headers["x-request-id"] = request_id
return response
finally:
latency_ms = round((time.perf_counter() - started) * 1000, 2)
logger.info(
"request.completed",
extra={"fields": {
"method": request.method,
"path": request.url.path,
"status": status_code,
"latency_ms": latency_ms,
"embedding_tokens": metrics.embedding_tokens,
"embedding_cost_usd": metrics.embedding_cost_usd,
}},
)
status_code starts at 500. On success, it's overwritten. On failure, the log says 500.
finally only uses variables that exist on every path: started, status_code, metrics. Never response.
The test went green.
The last post counted tokens. But I wanted the log to answer a simpler question: what did this request cost?
text-embedding-3-small is $0.02 per million tokens, per OpenAI's pricing page. I wrote a small calculator, test first, using Decimal. Floats are the wrong type for money.
Now the failed request from the opening shows up properly: status 500, the tokens it used, and what it cost. Before the fix, that money was spent and never recorded anywhere.
await is a log line that skips failures.finally runs every time. A return inside it hides errors. I wrote that bug while fixing another one.
Code: github.com/YusufOztoprak/evorag
I drafted this post with help from Claude; the code, bugs, and measurements are from my own work on evorag.