The quiet hour: what a stalled queue looked like from the outside
For fifty-one minutes every write succeeded and every read returned yesterday. Nothing alerted, because every check we had was asking the wrong question.
What happened
At 02:14 a routine index rebuild took a lock on the table our projection worker writes into. The worker did what it was told to do when it cannot write: it kept the message, waited, and tried again. It did that for fifty-one minutes without once reporting an error, because from its own point of view nothing had failed yet.
Everything downstream stayed up. The API answered, the dashboard rendered, health checks were green in three regions. What customers saw was a site that worked perfectly and showed them the state of the world as it had been just before two in the morning.
Why nothing alerted
Our checks measured three things: is the process running, is it consuming messages, and is the error rate low. All three were healthy. A worker that is patiently retrying is running, is holding its messages, and is producing no errors at all.
What we were not measuring was the only thing a reader cares about:
- How old is the newest record a customer can actually see
- How long has the oldest unacknowledged message been waiting
- Is the gap between those two growing
A health check that asks whether the machinery is turning cannot tell you that it is turning on the spot.
The timeline
All times are in UTC, taken from the worker's own log rather than reconstructed afterwards.
| Time | Event | Visible to customers |
|---|---|---|
| 02:14 | Index rebuild starts and takes the write lock | Nothing |
| 02:15 | Projection worker begins retrying, silently | Reads start going stale |
| 02:52 | A customer emails support about an old figure | Stale by 37 minutes |
| 03:01 | On-call paged by hand, incident opened | Status page updated |
| 03:06 | Rebuild cancelled, lock released, queue drains | Reads correct within 90 seconds |
The check we added
One number, published by the worker on every loop, whether or not it managed to write. Freshness is the age of the newest committed record, and it is the thing a customer would complain about if they could see it.
async function reportFreshness(db, metrics) {
const newest = await db.newestCommittedAt('projections');
const ageSeconds = (Date.now() - newest) / 1000;
// Published on every loop, including the loops where the write failed.
// A worker that goes quiet is as interesting as one reporting a big number.
metrics.gauge('projection.freshness_seconds', ageSeconds);
}The alert fires when freshness passes 120 seconds for two consecutive minutes. In the incident above it would have paged at 02:17, thirty-five minutes before the customer email, and about forty-four minutes before we actually found out.
What changes
Three things, all of them cheap, none of them clever. Index rebuilds now run behind a lease the worker can see, so it can log that it is blocked rather than retrying into the dark. Freshness is on the same dashboard as the error rate. And the runbook asks one question first: what is the oldest thing a customer can see right now.
If you take one thing from this, take the shape of the mistake rather than the fix. We measured the parts we owned and not the answer we give. Every check was true and the page was still wrong.