Request logging is lossy on purpose

Every request to the API leaves a row in `api_requests`: method, path, status, latency, bytes out. The write path for that row is deliberately allowed to lose data. The rate limiter, which decides whether you get a 429, does not read that table at all. This post explains why the two are separate and what it means for the numbers you see.

The problem

The obvious implementation is an `INSERT` in the request middleware. It adds a database round-trip to every response, and it couples the API's availability to the log's. If the connection pooler is slow or hung, a request that already succeeded gets slower or returns a 500 because telemetry could not be written. A usage log is the least important thing the API does, so it should be the first thing to give way.

The same reasoning applied to `api_keys.last_used_at`. It used to be updated with a synchronous `UPDATE` and `COMMIT` inside key authentication, a full round-trip on every authenticated request to write a timestamp nothing reads in real time. It now rides along in the log's batch flush.

Options considered

• Inline insert. Exact, simple, and puts a database write on the hot path. Rejected for the failure mode above.
• Fire-and-forget task per request. Off the hot path, but unbounded: a slow database turns into an ever-growing pile of pending tasks and connections.
• Bounded in-process queue with one background writer. Off the hot path, bounded memory, batched writes. Loses rows in a few specific cases.
• A durable queue, such as a Redis Stream with a separate consumer draining to Postgres. Survives a process restart, at the cost of another moving part and another failure path.

We chose the third and wrote down the fourth as the upgrade path. The log is for usage history and analytics, and for those a small, bounded loss is cheaper than the machinery needed to prevent it.

What we built

`enqueue()` in `app/request_log.py` calls `put_nowait` on an `asyncio.Queue` with a maximum size of 10,000 records and returns. It never blocks and never raises. A single background task takes the first record, then keeps accumulating for up to 0.5 seconds or 500 records, whichever comes first, and writes the batch with one `executemany`. The linger window means low traffic still coalesces into batches rather than one insert per request.

_MAX_QUEUE = 10_000
_LINGER_S = 0.5
_FLUSH_BATCH = 500
_SHUTDOWN_DRAIN_S = 3.0

def enqueue(record):
    try:
        _queue.put_nowait(record)
    except asyncio.QueueFull:
        _dropped += 1   # count it, keep serving

Each failure mode degrades to dropped rows and nothing else:

• Queue full. The record is dropped and counted, and a warning is logged on the first drop and every 1,000th after it. The queue is sized at roughly a few seconds of peak traffic, so reaching it means the writer has stalled.
• Flush fails. The batch is dropped with a warning and the writer carries on with the next one. The drain loop catches everything except cancellation so the writer cannot die quietly.
• Hard kill. Whatever is in the queue and in the batch the writer is holding is lost. On an orderly shutdown the writer is told to stop with a sentinel rather than cancelled, because a cancel during the linger window would discard a batch it had already taken off the queue. Shutdown then waits up to 3 seconds for the final drain.

Why the rate limiter must not depend on it

A dropped log row must never grant a caller extra quota, and a lagging log must never deny one. So enforcement does not touch the table. `enforce_rate_limit` in `app/rate_limit.py` does a Redis `INCR` on a per-key daily counter that expires at 00:00 UTC, and a second per-minute counter for burst protection. The count that decides whether you get a 429 is the count that was incremented by your request, atomically, before the handler runs.

The two stores are allowed to disagree because they answer different questions. Redis answers "how many has this key spent today", exactly, and forgets at midnight. Postgres answers "what happened", approximately, and keeps it. We recorded the rule in `apis/DECISIONS.md`: do not make a feature depend on the log being complete, and in particular not billing or quota enforcement, anything where a missing row costs money.

What the log captures

Method, concrete path, route template, path parameters, query parameters, status, latency and response size. Never request bodies, response bodies or headers. That is why logging `POST /v1/auth/register` is safe: the email is in the body and the issued key is in the response, and neither is ever read. Bearer tokens live in a header, so they cannot reach the table either. As defense in depth, query parameters named like secrets (`api_key`, `token`, `password` and similar) have their values replaced with `[redacted]` before the write.

There are two path columns on purpose. `endpoint` is the concrete path, `/v1/sec/filings/AAPL`. `route` is the template, `/v1/sec/filings/{symbol}`. Without the template every ticker is its own string and per-endpoint aggregation is impossible.

Retention: rollup first, prune second

Raw rows are a detail window, not an archive. The nightly job `ingest.rollup_api_requests` aggregates closed UTC days into `api_requests_daily` (request count, errors, bytes, p50, p95 and max latency per day, key, route and traffic source), then deletes raw rows older than `REQUEST_LOG_RETENTION_DAYS`, which defaults to 90. The order is the point: a crash between the two steps leaves the detail in place for the next run. The prune also only deletes days that already have a rollup row, and re-running a day overwrites its aggregate rather than double-counting. The daily table has no foreign key to the key table, so rotating a key does not erase its history.

How the stats pages reconcile

The public stats endpoint reads the rollup for days it covers and raw rows for days it does not, so days do not fall off the chart as raw rows age out. Where both exist the rollup wins. It also excludes our own test traffic and our own accounts, with a switch to put them back:

# Your own usage: today from Redis, this month from the request log
curl -H "Authorization: Bearer $HEDGEFRIEND_KEY" \
  https://api.hedgefriend.dev/v1/account/usage

# Public request volume, our own traffic excluded
curl https://api.hedgefriend.dev/v1/public/stats

{
  "tier": "free",
  "requests_per_day": 50,
  "requests_today": 17,
  "remaining_today": 33,
  "requests_this_month": 412
}

In `/v1/account/usage`, `requests_today` is read from the Redis counter, so it always agrees with what the limiter believes. `requests_this_month` is a count over the table. The public stats page counts the table too, for today and for history.

What this means for you

• Quota is exact. `X-RateLimit-Remaining` and `requests_today` come from the same counter that returns a 429.
• Usage history can lag. A request is normally visible in the log within about a second, and can be later if the writer is backed up.
• Usage history can undercount. After a restart with a non-empty queue, a database stall or a traffic spike past the queue, some rows are missing for good. We count queue-full drops in-process, but they are not exposed in the API.
• Monthly and public totals are therefore a floor, not an invoice. If you need to reconcile exactly, trust the remaining-quota header for the day.

Caveats

• We have not measured the loss rate and this post does not claim one. The drop counter is process-local and not exported, so we cannot currently say how many rows have been lost.
• The bound on loss in a hard kill is the queue plus the batch in hand, not only the 0.5 second linger window. Under a stalled writer that can be a large share of the 10,000 slots.
• The two surfaces can disagree on a single day: Redis says 17 and the table says 16. That is the design, not a bug.
• The rollup is computed from whatever rows made it into the table. A day's aggregate inherits that day's loss.

When this stops being acceptable

The decision holds while nothing money-bearing reads the log. If usage-based billing or contractual usage reporting arrives, the plan is already written: replace the `asyncio.Queue` with a Redis Stream, call `XADD` in `enqueue()`, and run a separate consumer that drains to Postgres. The `enqueue()` boundary was drawn so that change touches one file. Until then, the log stays cheap, bounded and allowed to be wrong in small ways, and the limiter stays exact.