Askr 1.6.0: it knew, and it told only itself

A production site had a queue lane that nothing was draining. For three days.

Askr diagnosed it correctly the entire time. Every ten seconds, its backlog watchdog worked out that jobs were piling up on a lane, named the queue, named the likely cause — and wrote that sentence to its own stderr, where it joined several million other lines nobody was reading.

Meanwhile: no failed jobs, because the jobs never ran. No admin warning, because there was no such thing. No health signal, because /up answered 200 throughout — the web workers were perfectly healthy, and they were. The dashboard was green. The queue depth was even in the admin API already, so a graph could have counted the jobs. What the graph could not do was learn that the count was wrong, because the threshold that made it wrong lived privately inside the supervisor.

This release is about that gap. Not "Askr couldn't tell" — Askr could tell. Askr knew. The conclusion just never left the building.

Why this is the whole release

There's a card on the Askr page called The failures used to be silent. Now it says so. It lists the faults on this project that cost somebody an afternoon: a queue nobody consumed, a worker polling the wrong queue name, a mailer under the vendor's variable instead of Laravel's, a scheduler shelling out to a php binary the image doesn't contain. Each one quiet. Each one now audible.

The card ends: this card is a record of what has been made audible, not a claim that nothing is left.

Three days of stderr is what was left.

So 1.6.0 moves the conclusion out of the log and into the API — and, on the way, sharpens the conclusion itself, because it turned out Askr had been answering a slightly wrong question all along.

The wrong question, and the right one

The old watchdog measured job age: how long has the oldest ready job been waiting? Over a threshold, warn.

That catches a stuck lane. It just can't tell you why it's stuck, and the two reasons have opposite remedies:

• Nothing is polling the lane. Your app dispatches ->onQueue('mail'); your worker polls default. The lane will never drain, ever, no matter what you do to capacity. This is nearly always a name mismatch, and it is nearly always the one that's happened.

• Workers are polling and the backlog still grows. You're saturated, or jobs are being released back onto the queue.

In job age, these look identical. And the old watchdog's single message — no worker is taking jobs from this queue — assumed the first. So an operator reading it during plain saturation was sent off to check a queue name that was perfectly correct, while the actual problem carried on.

1.6.0 measures the thing that tells them apart. A worker asking a lane for a job is recorded whether or not it gets one. A worker reserving a job is recorded separately. Polls and drains, counted apart:

polls drains verdict jobs waiting, nobody asking none none queue_unattended jobs waiting, workers asking, backlog grows yes some/none queue_not_draining

Verified both ways against a running server with an identical backlog: the same 40 waiting jobs classify as queue_not_draining when a worker polls that lane, and queue_unattended when it polls another. Same job age. Different diagnosis. That's the point.

How it reaches you

The API answers, so you don't reimplement it

GET /api/status gains a top-level warnings array. Empty when nothing is wrong:

{
  "warnings": [
    {
      "kind": "queue_unattended",
      "queue": "mail",
      "pending": 412,
      "oldest_pending_seconds": 254412,
      "seconds_since_poll": null,
      "detail": "412 jobs are ready on 'mail' and nothing has ever polled it. Workers are attached to 'default'. Check onQueue() against the worker's --queue."
    }
  ],
  "queues_idle": ["default", "notifications"]
}

Switch on kind; it's stable. detail is prose for a human and is not.

The reason this matters more than "one more endpoint" is the sentence underneath it: a consumer no longer reimplements Askr's thresholds to rediscover a conclusion Askr already reached. If your dashboard has its own idea of "too old" and Askr has another, they drift the next time either side changes, and you find out during an incident. The watchdog, the API and the Prometheus gauge now run one computation. They cannot disagree.

That queues_idle array looks like noise and is the opposite. "A worker is attached to default and there's nothing on it" is precisely the evidence that turns "nothing is attached to mail" from a guess into a diagnosis. A lane is remembered once polled, up to 64 distinct names.

Prometheus, per lane

askr_queue_pending_jobs{queue="mail"} 412
askr_queue_oldest_pending_seconds{queue="mail"} 254412
askr_queue_seconds_since_drain{queue="default"} 3
askr_queue_unattended{queue="mail"} 1

The old aggregates are unchanged and still can't answer which lane: a fleet-wide askr_queue_oldest_seconds is equally high whether one abandoned lane is ageing or every lane is merely busy — and only one of those is an incident.

One deliberate awkwardness worth knowing: seconds_since_poll and seconds_since_drain are absent for a lane where it has never happened, not 0. Emitting 0 would render as "just now", which is the exact opposite of the truth, and a graph that lies confidently is worse than a gap. Alert on absent() or on askr_queue_unattended:

- alert: AskrQueueUnattended
  expr: askr_queue_unattended == 1
  for: 2m
  annotations:
    summary: "No worker is polling {{ $labels.queue }}"

One knob

[queue]
stall_secs = 30   # default

How long a job may sit ready and unclaimed before Askr calls the lane stalled — in all three places at once. Ten seconds of queue latency is unremarkable; thirty means nothing is listening. Raise it for a deliberately batchy app, lower it to be told sooner.

Two documentation fixes that were really bugs

While writing the observability docs we read the Docker ones, and:

The quick-start did not start. docs/DOCKER.md opened with --admin 0.0.0.0:9000, while the same document said twice, further down, to use 127.0.0.1:9000. Since 1.5.1 a non-loopback admin bind refuses to start without ASKR_ADMIN_TOKEN — deliberately. So the first command in the Docker guide, run against the published 1.5.2 image, failed outright. The example compose file had the same bind, under a comment describing the opposite of what the code enforces.

The healthcheck probed the wrong path. The docs showed /api/status. The image has probed /healthz since that endpoint existed, precisely because /api/status requires a token once one is set, and a credentialed probe eventually declares a healthy container unhealthy. The documentation was teaching the exact mistake the endpoint exists to prevent.

Neither is glamorous. Both meant somebody's first ten minutes with Askr ended in a container that wouldn't come up.

And one fix with an honest footnote

Reviewing the new lane table turned up a race: an entry was claimed by writing the queue name and then compare-exchanging the hash. Two workers on different queues probing the same free slot would both write their name, and the winner published its hash over the loser's — so a lane could be reported under the wrong name. The claim is the compare-exchange now, with the name published after it.

Found in review, not in the field. And the regression test deserves a footnote we'd rather write than not:

It failed 0 times in 20 runs against the old ordering. The window is a few instructions wide. The test guards against someone reordering this code in future; it is not a reproducer, and nothing about it says the old ordering was safe.

A green test on the broken version means the test isn't the evidence. Saying so costs nothing and keeps the next person from trusting it for more than it's worth.

Try it

curl -s localhost:9000/api/status -H "Authorization: Bearer $ASKR_ADMIN_TOKEN" \
  | jq '.warnings'

On a healthy app that's [], which is a fine thing to see and a fine thing to alert on the absence of.

Then, if you'd like to watch it work: dispatch a job with ->onQueue('nowhere') and leave your worker where it is. Thirty seconds later the array has an entry, the gauge has a 1, and nobody has to read a log to find out.

Askr already knew. Now so do you.