I Paid for the Embedding. My Logs Never Saw the Request.

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.

Where it came from

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.

Test first

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 fix, and two new bugs

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.

The working version

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.

Tokens are not dollars

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.

What I learned

• I only tested the happy path. The bug lived in the path I didn't test.
• A log line placed after 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.
• Writing the failing test first kept me honest. It stayed red through my first "fix".
• Failed requests can still cost money. If you only log successes, you undercount your bill.

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.